igt@kms_flip@flip-vs-expired-vblank-interruptible@b-hdmi-a2 on shard-glk@IGT

Detail	Value
Duration	3.67 seconds
Hostname	shard-glk3
Igt-Version	IGT-Version: 2.4-g6b305d78c (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18478-g161329a551bb+ x86_64)
Out	Starting dynamic subtest: B-HDMI-A2 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 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-HDMI-A2: FAIL (3.672s)
Err	Starting dynamic subtest: B-HDMI-A2 [240.601109] (kms_flip:2488) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [240.601215] (kms_flip:2488) CRITICAL: Failed assertion: end - start < 500 [240.601300] (kms_flip:2488) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-HDMI-A2 failed. ** DEBUG [238.582888] (kms_flip:2488) DEBUG: Vblank took 22us [238.599775] (kms_flip:2488) DEBUG: name = flip last_ts = 238.778000 last_received_ts = 238.777542 last_seq = 4408 current_ts = 238.794678 current_received_ts = 238.794479 current_seq = 4409 count = 70 seq_step = 1 [238.599831] (kms_flip:2488) DEBUG: Vblank took 25us [238.616421] (kms_flip:2488) DEBUG: name = flip last_ts = 238.794678 last_received_ts = 238.794479 last_seq = 4409 current_ts = 238.811325 current_received_ts = 238.811127 current_seq = 4410 count = 71 seq_step = 1 [238.616471] (kms_flip:2488) DEBUG: Vblank took 22us [238.633196] (kms_flip:2488) DEBUG: name = flip last_ts = 238.811325 last_received_ts = 238.811127 last_seq = 4410 current_ts = 238.828003 current_received_ts = 238.827911 current_seq = 4411 count = 72 seq_step = 1 [238.633247] (kms_flip:2488) DEBUG: Vblank took 22us [238.649811] (kms_flip:2488) DEBUG: name = flip last_ts = 238.828003 last_received_ts = 238.827911 last_seq = 4411 current_ts = 238.844666 current_received_ts = 238.844513 current_seq = 4412 count = 73 seq_step = 1 [238.649863] (kms_flip:2488) DEBUG: Vblank took 22us [238.666121] (kms_flip:2488) DEBUG: name = flip last_ts = 238.844666 last_received_ts = 238.844513 last_seq = 4412 current_ts = 238.861328 current_received_ts = 238.860825 current_seq = 4413 count = 74 seq_step = 1 [238.666169] (kms_flip:2488) DEBUG: Vblank took 22us [238.683240] (kms_flip:2488) DEBUG: name = flip last_ts = 238.861328 last_received_ts = 238.860825 last_seq = 4413 current_ts = 238.878006 current_received_ts = 238.877945 current_seq = 4414 count = 75 seq_step = 1 [238.683322] (kms_flip:2488) DEBUG: Vblank took 21us [238.699755] (kms_flip:2488) DEBUG: name = flip last_ts = 238.878006 last_received_ts = 238.877945 last_seq = 4414 current_ts = 238.894669 current_received_ts = 238.894470 current_seq = 4415 count = 76 seq_step = 1 [238.699805] (kms_flip:2488) DEBUG: Vblank took 22us [238.716428] (kms_flip:2488) DEBUG: name = flip last_ts = 238.894669 last_received_ts = 238.894470 last_seq = 4415 current_ts = 238.911331 current_received_ts = 238.911133 current_seq = 4416 count = 77 seq_step = 1 [238.716475] (kms_flip:2488) DEBUG: Vblank took 21us [238.733204] (kms_flip:2488) DEBUG: name = flip last_ts = 238.911331 last_received_ts = 238.911133 last_seq = 4416 current_ts = 238.927994 current_received_ts = 238.927917 current_seq = 4417 count = 78 seq_step = 1 [238.733254] (kms_flip:2488) DEBUG: Vblank took 23us [238.750141] (kms_flip:2488) DEBUG: name = flip last_ts = 238.927994 last_received_ts = 238.927917 last_seq = 4417 current_ts = 238.944656 current_received_ts = 238.944855 current_seq = 4418 count = 79 seq_step = 1 [238.750190] (kms_flip:2488) DEBUG: Vblank took 22us [238.766154] (kms_flip:2488) DEBUG: name = flip last_ts = 238.944656 last_received_ts = 238.944855 last_seq = 4418 current_ts = 238.961334 current_received_ts = 238.960861 current_seq = 4419 count = 80 seq_step = 1 [238.766205] (kms_flip:2488) DEBUG: Vblank took 23us [238.783330] (kms_flip:2488) DEBUG: name = flip last_ts = 238.961334 last_received_ts = 238.960861 last_seq = 4419 current_ts = 238.977997 current_received_ts = 238.978043 current_seq = 4420 count = 81 seq_step = 1 [238.783378] (kms_flip:2488) DEBUG: Vblank took 22us [238.799754] (kms_flip:2488) DEBUG: name = flip last_ts = 238.977997 last_received_ts = 238.978043 last_seq = 4420 current_ts = 238.994675 current_received_ts = 238.994461 current_seq = 4421 count = 82 seq_step = 1 [238.800046] (kms_flip:2488) DEBUG: Vblank took 22us [238.816478] (kms_flip:2488) DEBUG: name = flip last_ts = 238.994675 last_received_ts = 238.994461 last_seq = 4421 current_ts = 239.011337 current_received_ts = 239.011185 current_seq = 4422 count = 83 seq_step = 1 [238.816542] (kms_flip:2488) DEBUG: Vblank took 24us [238.833197] (kms_flip:2488) DEBUG: name = flip last_ts = 239.011337 last_received_ts = 239.011185 last_seq = 4422 current_ts = 239.028000 current_received_ts = 239.027908 current_seq = 4423 count = 84 seq_step = 1 [238.833246] (kms_flip:2488) DEBUG: Vblank took 22us [238.850144] (kms_flip:2488) DEBUG: name = flip last_ts = 239.028000 last_received_ts = 239.027908 last_seq = 4423 current_ts = 239.044662 current_received_ts = 239.044861 current_seq = 4424 count = 85 seq_step = 1 [238.850194] (kms_flip:2488) DEBUG: Vblank took 24us [238.866142] (kms_flip:2488) DEBUG: name = flip last_ts = 239.044662 last_received_ts = 239.044861 last_seq = 4424 current_ts = 239.061340 current_received_ts = 239.060852 current_seq = 4425 count = 86 seq_step = 1 [238.866188] (kms_flip:2488) DEBUG: Vblank took 22us [238.882941] (kms_flip:2488) DEBUG: name = flip last_ts = 239.061340 last_received_ts = 239.060852 last_seq = 4425 current_ts = 239.077988 current_received_ts = 239.077652 current_seq = 4426 count = 87 seq_step = 1 [238.882996] (kms_flip:2488) DEBUG: Vblank took 25us [238.900209] (kms_flip:2488) DEBUG: name = flip last_ts = 239.077988 last_received_ts = 239.077652 last_seq = 4426 current_ts = 239.094666 current_received_ts = 239.094910 current_seq = 4427 count = 88 seq_step = 1 [238.900308] (kms_flip:2488) DEBUG: Vblank took 68us [238.916149] (kms_flip:2488) DEBUG: name = flip last_ts = 239.094666 last_received_ts = 239.094910 last_seq = 4427 current_ts = 239.111328 current_received_ts = 239.110855 current_seq = 4428 count = 89 seq_step = 1 [238.916198] (kms_flip:2488) DEBUG: Vblank took 23us [238.932867] (kms_flip:2488) DEBUG: name = flip last_ts = 239.111328 last_received_ts = 239.110855 last_seq = 4428 current_ts = 239.128006 current_received_ts = 239.127579 current_seq = 4429 count = 90 seq_step = 1 [238.932916] (kms_flip:2488) DEBUG: Vblank took 23us [238.949789] (kms_flip:2488) DEBUG: name = flip last_ts = 239.128006 last_received_ts = 239.127579 last_seq = 4429 current_ts = 239.144669 current_received_ts = 239.144501 current_seq = 4430 count = 91 seq_step = 1 [238.949839] (kms_flip:2488) DEBUG: Vblank took 23us [238.966445] (kms_flip:2488) DEBUG: name = flip last_ts = 239.144669 last_received_ts = 239.144501 last_seq = 4430 current_ts = 239.161331 current_received_ts = 239.161148 current_seq = 4431 count = 92 seq_step = 1 [238.966492] (kms_flip:2488) DEBUG: Vblank took 22us [238.982850] (kms_flip:2488) DEBUG: name = flip last_ts = 239.161331 last_received_ts = 239.161148 last_seq = 4431 current_ts = 239.177994 current_received_ts = 239.177567 current_seq = 4432 count = 93 seq_step = 1 [238.982900] (kms_flip:2488) DEBUG: Vblank took 23us [238.999808] (kms_flip:2488) DEBUG: name = flip last_ts = 239.177994 last_received_ts = 239.177567 last_seq = 4432 current_ts = 239.194672 current_received_ts = 239.194519 current_seq = 4433 count = 94 seq_step = 1 [238.999855] (kms_flip:2488) DEBUG: Vblank took 22us [239.016623] (kms_flip:2488) DEBUG: name = flip last_ts = 239.194672 last_received_ts = 239.194519 last_seq = 4433 current_ts = 239.211334 current_received_ts = 239.211334 current_seq = 4434 count = 95 seq_step = 1 [239.016672] (kms_flip:2488) DEBUG: Vblank took 23us [239.032860] (kms_flip:2488) DEBUG: name = flip last_ts = 239.211334 last_received_ts = 239.211334 last_seq = 4434 current_ts = 239.227997 current_received_ts = 239.227570 current_seq = 4435 count = 96 seq_step = 1 [239.032911] (kms_flip:2488) DEBUG: Vblank took 23us [239.049785] (kms_flip:2488) DEBUG: name = flip last_ts = 239.227997 last_received_ts = 239.227570 last_seq = 4435 current_ts = 239.244659 current_received_ts = 239.244492 current_seq = 4436 count = 97 seq_step = 1 [239.049837] (kms_flip:2488) DEBUG: Vblank took 22us [239.066120] (kms_flip:2488) DEBUG: name = flip last_ts = 239.244659 last_received_ts = 239.244492 last_seq = 4436 current_ts = 239.261337 current_received_ts = 239.260834 current_seq = 4437 count = 98 seq_step = 1 [239.066166] (kms_flip:2488) DEBUG: Vblank took 21us [239.083027] (kms_flip:2488) DEBUG: name = flip last_ts = 239.261337 last_received_ts = 239.260834 last_seq = 4437 current_ts = 239.278000 current_received_ts = 239.277740 current_seq = 4438 count = 99 seq_step = 1 [239.083072] (kms_flip:2488) DEBUG: Vblank took 21us [239.099803] (kms_flip:2488) DEBUG: name = flip last_ts = 239.278000 last_received_ts = 239.277740 last_seq = 4438 current_ts = 239.294678 current_received_ts = 239.294510 current_seq = 4439 count = 100 seq_step = 1 [239.099883] (kms_flip:2488) DEBUG: Vblank took 23us [239.116428] (kms_flip:2488) DEBUG: name = flip last_ts = 239.294678 last_received_ts = 239.294510 last_seq = 4439 current_ts = 239.311340 current_received_ts = 239.311142 current_seq = 4440 count = 101 seq_step = 1 [239.116477] (kms_flip:2488) DEBUG: Vblank took 22us [239.132828] (kms_flip:2488) DEBUG: name = flip last_ts = 239.311340 last_received_ts = 239.311142 last_seq = 4440 current_ts = 239.328003 current_received_ts = 239.327530 current_seq = 4441 count = 102 seq_step = 1 [239.132880] (kms_flip:2488) DEBUG: Vblank took 23us [239.149756] (kms_flip:2488) DEBUG: name = flip last_ts = 239.328003 last_received_ts = 239.327530 last_seq = 4441 current_ts = 239.344666 current_received_ts = 239.344467 current_seq = 4442 count = 103 seq_step = 1 [239.149810] (kms_flip:2488) DEBUG: Vblank took 25us [239.166130] (kms_flip:2488) DEBUG: name = flip last_ts = 239.344666 last_received_ts = 239.344467 last_seq = 4442 current_ts = 239.361343 current_received_ts = 239.360840 current_seq = 4443 count = 104 seq_step = 1 [239.166180] (kms_flip:2488) DEBUG: Vblank took 23us [239.182954] (kms_flip:2488) DEBUG: name = flip last_ts = 239.361343 last_received_ts = 239.360840 last_seq = 4443 current_ts = 239.378006 current_received_ts = 239.377670 current_seq = 4444 count = 105 seq_step = 1 [239.183005] (kms_flip:2488) DEBUG: Vblank took 24us [239.199770] (kms_flip:2488) DEBUG: name = flip last_ts = 239.378006 last_received_ts = 239.377670 last_seq = 4444 current_ts = 239.394669 current_received_ts = 239.394485 current_seq = 4445 count = 106 seq_step = 1 [239.199821] (kms_flip:2488) DEBUG: Vblank took 23us [239.216512] (kms_flip:2488) DEBUG: name = flip last_ts = 239.394669 last_received_ts = 239.394485 last_seq = 4445 current_ts = 239.411331 current_received_ts = 239.411224 current_seq = 4446 count = 107 seq_step = 1 [239.216566] (kms_flip:2488) DEBUG: Vblank took 25us [239.233236] (kms_flip:2488) DEBUG: name = flip last_ts = 239.411331 last_received_ts = 239.411224 last_seq = 4446 current_ts = 239.427994 current_received_ts = 239.427948 current_seq = 4447 count = 108 seq_step = 1 [239.233329] (kms_flip:2488) DEBUG: Vblank took 23us [239.250128] (kms_flip:2488) DEBUG: name = flip last_ts = 239.427994 last_received_ts = 239.427948 last_seq = 4447 current_ts = 239.444672 current_received_ts = 239.444839 current_seq = 4448 count = 109 seq_step = 1 [239.250178] (kms_flip:2488) DEBUG: Vblank took 22us [239.266122] (kms_flip:2488) DEBUG: name = flip last_ts = 239.444672 last_received_ts = 239.444839 last_seq = 4448 current_ts = 239.461334 current_received_ts = 239.460831 current_seq = 4449 count = 110 seq_step = 1 [239.266168] (kms_flip:2488) DEBUG: Vblank took 22us [239.282850] (kms_flip:2488) DEBUG: name = flip last_ts = 239.461334 last_received_ts = 239.460831 last_seq = 4449 current_ts = 239.478012 current_received_ts = 239.477554 current_seq = 4450 count = 111 seq_step = 1 [239.282901] (kms_flip:2488) DEBUG: Vblank took 24us [239.299815] (kms_flip:2488) DEBUG: name = flip last_ts = 239.478012 last_received_ts = 239.477554 last_seq = 4450 current_ts = 239.494675 current_received_ts = 239.494522 current_seq = 4451 count = 112 seq_step = 1 [239.299868] (kms_flip:2488) DEBUG: Vblank took 24us [239.316120] (kms_flip:2488) DEBUG: name = flip last_ts = 239.494675 last_received_ts = 239.494522 last_seq = 4451 current_ts = 239.511337 current_received_ts = 239.510834 current_seq = 4452 count = 113 seq_step = 1 [239.316166] (kms_flip:2488) DEBUG: Vblank took 22us [239.332945] (kms_flip:2488) DEBUG: name = flip last_ts = 239.511337 last_received_ts = 239.510834 last_seq = 4452 current_ts = 239.528000 current_received_ts = 239.527664 current_seq = 4453 count = 114 seq_step = 1 [239.332992] (kms_flip:2488) DEBUG: Vblank took 22us [239.349761] (kms_flip:2488) DEBUG: name = flip last_ts = 239.528000 last_received_ts = 239.527664 last_seq = 4453 current_ts = 239.544678 current_received_ts = 239.544464 current_seq = 4454 count = 115 seq_step = 1 [239.349813] (kms_flip:2488) DEBUG: Vblank took 23us [239.366445] (kms_flip:2488) DEBUG: name = flip last_ts = 239.544678 last_received_ts = 239.544464 last_seq = 4454 current_ts = 239.561325 current_received_ts = 239.561157 current_seq = 4455 count = 116 seq_step = 1 [239.366496] (kms_flip:2488) DEBUG: Vblank took 23us [239.382784] (kms_flip:2488) DEBUG: name = flip last_ts = 239.561325 last_received_ts = 239.561157 last_seq = 4455 current_ts = 239.577988 current_received_ts = 239.577499 current_seq = 4456 count = 117 seq_step = 1 [239.382837] (kms_flip:2488) DEBUG: Vblank took 24us [239.399936] (kms_flip:2488) DEBUG: name = flip last_ts = 239.577988 last_received_ts = 239.577499 last_seq = 4456 current_ts = 239.594666 current_received_ts = 239.594650 current_seq = 4457 count = 118 seq_step = 1 [239.399982] (kms_flip:2488) DEBUG: Vblank took 22us [239.416519] (kms_flip:2488) DEBUG: name = flip last_ts = 239.594666 last_received_ts = 239.594650 last_seq = 4457 current_ts = 239.611328 current_received_ts = 239.611237 current_seq = 4458 count = 119 seq_step = 1 [239.416594] (kms_flip:2488) DEBUG: Vblank took 23us [239.432856] (kms_flip:2488) DEBUG: name = flip last_ts = 239.611328 last_received_ts = 239.611237 last_seq = 4458 current_ts = 239.628006 current_received_ts = 239.627563 current_seq = 4459 count = 120 seq_step = 1 [239.432904] (kms_flip:2488) DEBUG: Vblank took 23us [239.449660] (kms_flip:2488) DEBUG: name = flip last_ts = 239.628006 last_received_ts = 239.627563 last_seq = 4459 current_ts = 239.644669 current_received_ts = 239.644363 current_seq = 4460 count = 121 seq_step = 1 [239.449707] (kms_flip:2488) DEBUG: Vblank took 23us [239.466907] (kms_flip:2488) DEBUG: name = flip last_ts = 239.644669 last_received_ts = 239.644363 last_seq = 4460 current_ts = 239.661331 current_received_ts = 239.661621 current_seq = 4461 count = 122 seq_step = 1 [239.466952] (kms_flip:2488) DEBUG: Vblank took 22us [239.483321] (kms_flip:2488) DEBUG: name = flip last_ts = 239.661331 last_received_ts = 239.661621 last_seq = 4461 current_ts = 239.678009 current_received_ts = 239.677979 current_seq = 4462 count = 123 seq_step = 1 [239.483374] (kms_flip:2488) DEBUG: Vblank took 26us [239.499814] (kms_flip:2488) DEBUG: name = flip last_ts = 239.678009 last_received_ts = 239.677979 last_seq = 4462 current_ts = 239.694672 current_received_ts = 239.694519 current_seq = 4463 count = 124 seq_step = 1 [239.499864] (kms_flip:2488) DEBUG: Vblank took 25us [239.516464] (kms_flip:2488) DEBUG: name = flip last_ts = 239.694672 last_received_ts = 239.694519 last_seq = 4463 current_ts = 239.711334 current_received_ts = 239.711182 current_seq = 4464 count = 125 seq_step = 1 [239.516514] (kms_flip:2488) DEBUG: Vblank took 23us [239.532833] (kms_flip:2488) DEBUG: name = flip last_ts = 239.711334 last_received_ts = 239.711182 last_seq = 4464 current_ts = 239.727997 current_received_ts = 239.727539 current_seq = 4465 count = 126 seq_step = 1 [239.532885] (kms_flip:2488) DEBUG: Vblank took 24us [239.549958] (kms_flip:2488) DEBUG: name = flip last_ts = 239.727997 last_received_ts = 239.727539 last_seq = 4465 current_ts = 239.744675 current_received_ts = 239.744675 current_seq = 4466 count = 127 seq_step = 1 [239.550003] (kms_flip:2488) DEBUG: Vblank took 22us [239.566468] (kms_flip:2488) DEBUG: name = flip last_ts = 239.744675 last_received_ts = 239.744675 last_seq = 4466 current_ts = 239.761337 current_received_ts = 239.761185 current_seq = 4467 count = 128 seq_step = 1 [239.566519] (kms_flip:2488) DEBUG: Vblank took 23us [239.583195] (kms_flip:2488) DEBUG: name = flip last_ts = 239.761337 last_received_ts = 239.761185 last_seq = 4467 current_ts = 239.778000 current_received_ts = 239.777908 current_seq = 4468 count = 129 seq_step = 1 [239.583245] (kms_flip:2488) DEBUG: Vblank took 23us [239.599805] (kms_flip:2488) DEBUG: name = flip last_ts = 239.778000 last_received_ts = 239.777908 last_seq = 4468 current_ts = 239.794662 current_received_ts = 239.794510 current_seq = 4469 count = 130 seq_step = 1 [239.599855] (kms_flip:2488) DEBUG: Vblank took 23us [239.616842] (kms_flip:2488) DEBUG: name = flip last_ts = 239.794662 last_received_ts = 239.794510 last_seq = 4469 current_ts = 239.811340 current_received_ts = 239.811554 current_seq = 4470 count = 131 seq_step = 1 [239.616889] (kms_flip:2488) DEBUG: Vblank took 22us [239.632879] (kms_flip:2488) DEBUG: name = flip last_ts = 239.811340 last_received_ts = 239.811554 last_seq = 4470 current_ts = 239.828003 current_received_ts = 239.827591 current_seq = 4471 count = 132 seq_step = 1 [239.632933] (kms_flip:2488) DEBUG: Vblank took 24us [239.649809] (kms_flip:2488) DEBUG: name = flip last_ts = 239.828003 last_received_ts = 239.827591 last_seq = 4471 current_ts = 239.844666 current_received_ts = 239.844513 current_seq = 4472 count = 133 seq_step = 1 [239.649860] (kms_flip:2488) DEBUG: Vblank took 23us [239.666148] (kms_flip:2488) DEBUG: name = flip last_ts = 239.844666 last_received_ts = 239.844513 last_seq = 4472 current_ts = 239.861343 current_received_ts = 239.860855 current_seq = 4473 count = 134 seq_step = 1 [239.666195] (kms_flip:2488) DEBUG: Vblank took 22us [239.682941] (kms_flip:2488) DEBUG: name = flip last_ts = 239.861343 last_received_ts = 239.860855 last_seq = 4473 current_ts = 239.878006 current_received_ts = 239.877655 current_seq = 4474 count = 135 seq_step = 1 [239.682991] (kms_flip:2488) DEBUG: Vblank took 24us [239.699877] (kms_flip:2488) DEBUG: name = flip last_ts = 239.878006 last_received_ts = 239.877655 last_seq = 4474 current_ts = 239.894669 current_received_ts = 239.894592 current_seq = 4475 count = 136 seq_step = 1 [239.699927] (kms_flip:2488) DEBUG: Vblank took 23us [239.716450] (kms_flip:2488) DEBUG: name = flip last_ts = 239.894669 last_received_ts = 239.894592 last_seq = 4475 current_ts = 239.911331 current_received_ts = 239.911163 current_seq = 4476 count = 137 seq_step = 1 [239.716499] (kms_flip:2488) DEBUG: Vblank took 23us [239.733212] (kms_flip:2488) DEBUG: name = flip last_ts = 239.911331 last_received_ts = 239.911163 last_seq = 4476 current_ts = 239.927994 current_received_ts = 239.927917 current_seq = 4477 count = 138 seq_step = 1 [239.733299] (kms_flip:2488) DEBUG: Vblank took 60us [239.749804] (kms_flip:2488) DEBUG: name = flip last_ts = 239.927994 last_received_ts = 239.927917 last_seq = 4477 current_ts = 239.944656 current_received_ts = 239.944519 current_seq = 4478 count = 139 seq_step = 1 [239.749855] (kms_flip:2488) DEBUG: Vblank took 23us [239.766234] (kms_flip:2488) DEBUG: name = flip last_ts = 239.944656 last_received_ts = 239.944519 last_seq = 4478 current_ts = 239.961334 current_received_ts = 239.960938 current_seq = 4479 count = 140 seq_step = 1 [239.766332] (kms_flip:2488) DEBUG: Vblank took 32us [239.783017] (kms_flip:2488) DEBUG: name = flip last_ts = 239.961334 last_received_ts = 239.960938 last_seq = 4479 current_ts = 239.977997 current_received_ts = 239.977737 current_seq = 4480 count = 141 seq_step = 1 [239.783062] (kms_flip:2488) DEBUG: Vblank took 22us [239.799859] (kms_flip:2488) DEBUG: name = flip last_ts = 239.977997 last_received_ts = 239.977737 last_seq = 4480 current_ts = 239.994659 current_received_ts = 239.994537 current_seq = 4481 count = 142 seq_step = 1 [239.799910] (kms_flip:2488) DEBUG: Vblank took 23us [239.816485] (kms_flip:2488) DEBUG: name = flip last_ts = 239.994659 last_received_ts = 239.994537 last_seq = 4481 current_ts = 240.011337 current_received_ts = 240.011200 current_seq = 4482 count = 143 seq_step = 1 [239.816533] (kms_flip:2488) DEBUG: Vblank took 22us [239.833175] (kms_flip:2488) DEBUG: name = flip last_ts = 240.011337 last_received_ts = 240.011200 last_seq = 4482 current_ts = 240.028000 current_received_ts = 240.027893 current_seq = 4483 count = 144 seq_step = 1 [239.833223] (kms_flip:2488) DEBUG: Vblank took 22us [239.849819] (kms_flip:2488) DEBUG: name = flip last_ts = 240.028000 last_received_ts = 240.027893 last_seq = 4483 current_ts = 240.044678 current_received_ts = 240.044525 current_seq = 4484 count = 145 seq_step = 1 [239.849869] (kms_flip:2488) DEBUG: Vblank took 24us [239.866072] (kms_flip:2488) DEBUG: name = flip last_ts = 240.044678 last_received_ts = 240.044525 last_seq = 4484 current_ts = 240.061340 current_received_ts = 240.060791 current_seq = 4485 count = 146 seq_step = 1 [239.866119] (kms_flip:2488) DEBUG: Vblank took 22us [239.882844] (kms_flip:2488) DEBUG: name = flip last_ts = 240.061340 last_received_ts = 240.060791 last_seq = 4485 current_ts = 240.078003 current_received_ts = 240.077560 current_seq = 4486 count = 147 seq_step = 1 [239.882895] (kms_flip:2488) DEBUG: Vblank took 23us [239.899790] (kms_flip:2488) DEBUG: name = flip last_ts = 240.078003 last_received_ts = 240.077560 last_seq = 4486 current_ts = 240.094681 current_received_ts = 240.094498 current_seq = 4487 count = 148 seq_step = 1 [239.899842] (kms_flip:2488) DEBUG: Vblank took 25us [239.916438] (kms_flip:2488) DEBUG: name = flip last_ts = 240.094681 last_received_ts = 240.094498 last_seq = 4487 current_ts = 240.111328 current_received_ts = 240.111145 current_seq = 4488 count = 149 seq_step = 1 [239.916487] (kms_flip:2488) DEBUG: Vblank took 22us [239.932796] (kms_flip:2488) DEBUG: name = flip last_ts = 240.111328 last_received_ts = 240.111145 last_seq = 4488 current_ts = 240.128006 current_received_ts = 240.127502 current_seq = 4489 count = 150 seq_step = 1 [239.932844] (kms_flip:2488) DEBUG: Vblank took 23us [239.950210] (kms_flip:2488) DEBUG: name = flip last_ts = 240.128006 last_received_ts = 240.127502 last_seq = 4489 current_ts = 240.144669 current_received_ts = 240.144928 current_seq = 4490 count = 151 seq_step = 1 [239.950290] (kms_flip:2488) DEBUG: Vblank took 22us [239.966456] (kms_flip:2488) DEBUG: name = flip last_ts = 240.144669 last_received_ts = 240.144928 last_seq = 4490 current_ts = 240.161331 current_received_ts = 240.161163 current_seq = 4491 count = 152 seq_step = 1 [239.966510] (kms_flip:2488) DEBUG: Vblank took 25us [239.982833] (kms_flip:2488) DEBUG: name = flip last_ts = 240.161331 last_received_ts = 240.161163 last_seq = 4491 current_ts = 240.178009 current_received_ts = 240.177551 current_seq = 4492 count = 153 seq_step = 1 [239.982884] (kms_flip:2488) DEBUG: Vblank took 24us [240.000243] (kms_flip:2488) DEBUG: name = flip last_ts = 240.178009 last_received_ts = 240.177551 last_seq = 4492 current_ts = 240.194656 current_received_ts = 240.194962 current_seq = 4493 count = 154 seq_step = 1 [240.000335] (kms_flip:2488) DEBUG: Vblank took 23us [240.016150] (kms_flip:2488) DEBUG: name = flip last_ts = 240.194656 last_received_ts = 240.194962 last_seq = 4493 current_ts = 240.211334 current_received_ts = 240.210861 current_seq = 4494 count = 155 seq_step = 1 [240.016200] (kms_flip:2488) DEBUG: Vblank took 22us [240.033256] (kms_flip:2488) DEBUG: name = flip last_ts = 240.211334 last_received_ts = 240.210861 last_seq = 4494 current_ts = 240.227997 current_received_ts = 240.227966 current_seq = 4495 count = 156 seq_step = 1 [240.033414] (kms_flip:2488) DEBUG: Vblank took 20us [240.050048] (kms_flip:2488) DEBUG: name = flip last_ts = 240.227997 last_received_ts = 240.227966 last_seq = 4495 current_ts = 240.244659 current_received_ts = 240.244751 current_seq = 4496 count = 157 seq_step = 1 [240.050100] (kms_flip:2488) DEBUG: Vblank took 24us [240.066409] (kms_flip:2488) DEBUG: name = flip last_ts = 240.244659 last_received_ts = 240.244751 last_seq = 4496 current_ts = 240.261337 current_received_ts = 240.261124 current_seq = 4497 count = 158 seq_step = 1 [240.066459] (kms_flip:2488) DEBUG: Vblank took 22us [240.083241] (kms_flip:2488) DEBUG: name = flip last_ts = 240.261337 last_received_ts = 240.261124 last_seq = 4497 current_ts = 240.278000 current_received_ts = 240.277954 current_seq = 4498 count = 159 seq_step = 1 [240.083333] (kms_flip:2488) DEBUG: Vblank took 24us [240.100154] (kms_flip:2488) DEBUG: name = flip last_ts = 240.278000 last_received_ts = 240.277954 last_seq = 4498 current_ts = 240.294662 current_received_ts = 240.294861 current_seq = 4499 count = 160 seq_step = 1 [240.100206] (kms_flip:2488) DEBUG: Vblank took 24us [240.116535] (kms_flip:2488) DEBUG: name = flip last_ts = 240.294662 last_received_ts = 240.294861 last_seq = 4499 current_ts = 240.311340 current_received_ts = 240.311249 current_seq = 4500 count = 161 seq_step = 1 [240.116584] (kms_flip:2488) DEBUG: Vblank took 23us [240.133026] (kms_flip:2488) DEBUG: name = flip last_ts = 240.311340 last_received_ts = 240.311249 last_seq = 4500 current_ts = 240.328003 current_received_ts = 240.327744 current_seq = 4501 count = 162 seq_step = 1 [240.133072] (kms_flip:2488) DEBUG: Vblank took 21us [240.149818] (kms_flip:2488) DEBUG: name = flip last_ts = 240.328003 last_received_ts = 240.327744 last_seq = 4501 current_ts = 240.344666 current_received_ts = 240.344528 current_seq = 4502 count = 163 seq_step = 1 [240.149892] (kms_flip:2488) DEBUG: Vblank took 47us [240.166455] (kms_flip:2488) DEBUG: name = flip last_ts = 240.344666 last_received_ts = 240.344528 last_seq = 4502 current_ts = 240.361328 current_received_ts = 240.361176 current_seq = 4503 count = 164 seq_step = 1 [240.166503] (kms_flip:2488) DEBUG: Vblank took 21us [240.182790] (kms_flip:2488) DEBUG: name = flip last_ts = 240.361328 last_received_ts = 240.361176 last_seq = 4503 current_ts = 240.378006 current_received_ts = 240.377502 current_seq = 4504 count = 165 seq_step = 1 [240.182840] (kms_flip:2488) DEBUG: Vblank took 23us [240.200220] (kms_flip:2488) DEBUG: name = flip last_ts = 240.378006 last_received_ts = 240.377502 last_seq = 4504 current_ts = 240.394669 current_received_ts = 240.394928 current_seq = 4505 count = 166 seq_step = 1 [240.200304] (kms_flip:2488) DEBUG: Vblank took 58us [240.216429] (kms_flip:2488) DEBUG: name = flip last_ts = 240.394669 last_received_ts = 240.394928 last_seq = 4505 current_ts = 240.411331 current_received_ts = 240.411148 current_seq = 4506 count = 167 seq_step = 1 [240.216479] (kms_flip:2488) DEBUG: Vblank took 22us [240.232825] (kms_flip:2488) DEBUG: name = flip last_ts = 240.411331 last_received_ts = 240.411148 last_seq = 4506 current_ts = 240.428009 current_received_ts = 240.427536 current_seq = 4507 count = 168 seq_step = 1 [240.232878] (kms_flip:2488) DEBUG: Vblank took 24us [240.250155] (kms_flip:2488) DEBUG: name = flip last_ts = 240.428009 last_received_ts = 240.427536 last_seq = 4507 current_ts = 240.444672 current_received_ts = 240.444870 current_seq = 4508 count = 169 seq_step = 1 [240.250204] (kms_flip:2488) DEBUG: Vblank took 23us [240.266077] (kms_flip:2488) DEBUG: name = flip last_ts = 240.444672 last_received_ts = 240.444870 last_seq = 4508 current_ts = 240.461334 current_received_ts = 240.460785 current_seq = 4509 count = 170 seq_step = 1 [240.266126] (kms_flip:2488) DEBUG: Vblank took 23us [240.282838] (kms_flip:2488) DEBUG: name = flip last_ts = 240.461334 last_received_ts = 240.460785 last_seq = 4509 current_ts = 240.477997 current_received_ts = 240.477554 current_seq = 4510 count = 171 seq_step = 1 [240.282888] (kms_flip:2488) DEBUG: Vblank took 22us [240.299747] (kms_flip:2488) DEBUG: name = flip last_ts = 240.477997 last_received_ts = 240.477554 last_seq = 4510 current_ts = 240.494675 current_received_ts = 240.494461 current_seq = 4511 count = 172 seq_step = 1 [240.299800] (kms_flip:2488) DEBUG: Vblank took 23us [240.316421] (kms_flip:2488) DEBUG: name = flip last_ts = 240.494675 last_received_ts = 240.494461 last_seq = 4511 current_ts = 240.511337 current_received_ts = 240.511139 current_seq = 4512 count = 173 seq_step = 1 [240.316471] (kms_flip:2488) DEBUG: Vblank took 22us [240.332819] (kms_flip:2488) DEBUG: name = flip last_ts = 240.511337 last_received_ts = 240.511139 last_seq = 4512 current_ts = 240.528000 current_received_ts = 240.527527 current_seq = 4513 count = 174 seq_step = 1 [240.332871] (kms_flip:2488) DEBUG: Vblank took 24us [240.349812] (kms_flip:2488) DEBUG: name = flip last_ts = 240.528000 last_received_ts = 240.527527 last_seq = 4513 current_ts = 240.544662 current_received_ts = 240.544525 current_seq = 4514 count = 175 seq_step = 1 [240.349864] (kms_flip:2488) DEBUG: Vblank took 23us [240.366838] (kms_flip:2488) DEBUG: name = flip last_ts = 240.544662 last_received_ts = 240.544525 last_seq = 4514 current_ts = 240.561325 current_received_ts = 240.561554 current_seq = 4515 count = 176 seq_step = 1 [240.366882] (kms_flip:2488) DEBUG: Vblank took 21us [240.382850] (kms_flip:2488) DEBUG: name = flip last_ts = 240.561325 last_received_ts = 240.561554 last_seq = 4515 current_ts = 240.578003 current_received_ts = 240.577560 current_seq = 4516 count = 177 seq_step = 1 [240.382903] (kms_flip:2488) DEBUG: Vblank took 24us [240.399841] (kms_flip:2488) DEBUG: name = flip last_ts = 240.578003 last_received_ts = 240.577560 last_seq = 4516 current_ts = 240.594666 current_received_ts = 240.594559 current_seq = 4517 count = 178 seq_step = 1 [240.399893] (kms_flip:2488) DEBUG: Vblank took 23us [240.416417] (kms_flip:2488) DEBUG: name = flip last_ts = 240.594666 last_received_ts = 240.594559 last_seq = 4517 current_ts = 240.611343 current_received_ts = 240.611130 current_seq = 4518 count = 179 seq_step = 1 [240.416460] (kms_flip:2488) DEBUG: Vblank took 20us [240.432828] (kms_flip:2488) DEBUG: name = flip last_ts = 240.611343 last_received_ts = 240.611130 last_seq = 4518 current_ts = 240.628006 current_received_ts = 240.627533 current_seq = 4519 count = 180 seq_step = 1 [240.432879] (kms_flip:2488) DEBUG: Vblank took 23us [240.450126] (kms_flip:2488) DEBUG: name = flip last_ts = 240.628006 last_received_ts = 240.627533 last_seq = 4519 current_ts = 240.644669 current_received_ts = 240.644836 current_seq = 4520 count = 181 seq_step = 1 [240.450175] (kms_flip:2488) DEBUG: Vblank took 22us [240.466153] (kms_flip:2488) DEBUG: name = flip last_ts = 240.644669 last_received_ts = 240.644836 last_seq = 4520 current_ts = 240.661346 current_received_ts = 240.660873 current_seq = 4521 count = 182 seq_step = 1 [240.466202] (kms_flip:2488) DEBUG: Vblank took 23us [240.482954] (kms_flip:2488) DEBUG: name = flip last_ts = 240.661346 last_received_ts = 240.660873 last_seq = 4521 current_ts = 240.677994 current_received_ts = 240.677673 current_seq = 4522 count = 183 seq_step = 1 [240.483002] (kms_flip:2488) DEBUG: Vblank took 22us [240.499871] (kms_flip:2488) DEBUG: name = flip last_ts = 240.677994 last_received_ts = 240.677673 last_seq = 4522 current_ts = 240.694672 current_received_ts = 240.694550 current_seq = 4523 count = 184 seq_step = 1 [240.499921] (kms_flip:2488) DEBUG: Vblank took 23us [240.516447] (kms_flip:2488) DEBUG: name = flip last_ts = 240.694672 last_received_ts = 240.694550 last_seq = 4523 current_ts = 240.711334 current_received_ts = 240.711166 current_seq = 4524 count = 185 seq_step = 1 [240.516495] (kms_flip:2488) DEBUG: Vblank took 23us [240.532838] (kms_flip:2488) DEBUG: name = flip last_ts = 240.711334 last_received_ts = 240.711166 last_seq = 4524 current_ts = 240.727997 current_received_ts = 240.727554 current_seq = 4525 count = 186 seq_step = 1 [240.532888] (kms_flip:2488) DEBUG: Vblank took 23us [240.549798] (kms_flip:2488) DEBUG: name = flip last_ts = 240.727997 last_received_ts = 240.727554 last_seq = 4525 current_ts = 240.744675 current_received_ts = 240.744507 current_seq = 4526 count = 187 seq_step = 1 [240.549848] (kms_flip:2488) DEBUG: Vblank took 24us [240.566165] (kms_flip:2488) DEBUG: name = flip last_ts = 240.744675 last_received_ts = 240.744507 last_seq = 4526 current_ts = 240.761337 current_received_ts = 240.760880 current_seq = 4527 count = 188 seq_step = 1 [240.566213] (kms_flip:2488) DEBUG: Vblank took 22us [240.583044] (kms_flip:2488) DEBUG: name = flip last_ts = 240.761337 last_received_ts = 240.760880 last_seq = 4527 current_ts = 240.778000 current_received_ts = 240.777756 current_seq = 4528 count = 189 seq_step = 1 [240.583090] (kms_flip:2488) DEBUG: Vblank took 22us [240.599815] (kms_flip:2488) DEBUG: name = flip last_ts = 240.778000 last_received_ts = 240.777756 last_seq = 4528 current_ts = 240.794678 current_received_ts = 240.794525 current_seq = 4529 count = 190 seq_step = 1 [240.601098] (kms_flip:2488) DEBUG: Vblank took 1258us [240.601109] (kms_flip:2488) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [240.601215] (kms_flip:2488) CRITICAL: Failed assertion: end - start < 500 [240.601300] (kms_flip:2488) CRITICAL: Last errno: 4, Interrupted system call [240.608303] (kms_flip:2488) igt_core-INFO: Stack trace: [240.617769] (kms_flip:2488) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [240.619614] (kms_flip:2488) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [240.619809] (kms_flip:2488) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [240.619883] (kms_flip:2488) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [240.619968] (kms_flip:2488) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [240.634630] (kms_flip:2488) igt_core-INFO: #5 [__libc_init_first+0x8a] [240.636891] (kms_flip:2488) igt_core-INFO: #6 [__libc_start_main+0x8b] [240.637495] (kms_flip:2488) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-HDMI-A2: FAIL (3.672s)
Dmesg	<6> [237.268513] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2 <7> [237.269997] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180] <7> [237.270426] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182] <7> [237.307987] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A] <7> [237.308327] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [237.309000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [237.309562] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [237.310216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [237.310788] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000) <7> [237.311309] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [237.311947] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [237.312334] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [237.312755] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0) <7> [237.313135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [237.313551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0) <7> [237.313956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [237.314335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0) <7> [237.314737] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [237.315127] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [237.315519] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0) <7> [237.316000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0) <7> [237.316388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [237.316883] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [237.317325] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [237.317763] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0) <7> [237.318143] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [237.318575] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0) <7> [237.318996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [237.319378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0) <7> [237.319802] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [237.320214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [237.320591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0) <7> [237.321003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0) <7> [237.321406] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [237.321813] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [237.322192] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [237.322570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [237.322992] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [237.323371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no) <7> [237.323790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected yes, found no) <7> [237.324172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0) <7> [237.324574] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0) <7> [237.324981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0) <7> [237.325447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 222750, found 0) <7> [237.325859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000) <7> [237.326259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000) <7> [237.326738] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe <7> [237.327137] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.327516] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [237.327521] i915 0000:00:02.0: colorspace: RGB <7> [237.327525] i915 0000:00:02.0: scan mode: Underscan <7> [237.327528] i915 0000:00:02.0: colorimetry: No Data <7> [237.327531] i915 0000:00:02.0: picture aspect: No Data <7> [237.327534] i915 0000:00:02.0: active aspect: Same as Picture <7> [237.327537] i915 0000:00:02.0: itc: No Data <7> [237.327540] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [237.327543] i915 0000:00:02.0: quantization range: Full <7> [237.327546] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [237.327549] i915 0000:00:02.0: video code: 0 <7> [237.327552] i915 0000:00:02.0: ycc quantization range: Full <7> [237.327555] i915 0000:00:02.0: hdmi content type: Graphics <7> [237.327558] i915 0000:00:02.0: pixel repeat: 0 <7> [237.327561] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [237.327565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.328008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe <7> [237.328388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.328808] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [237.328813] i915 0000:00:02.0: vendor: Intel <7> [237.328816] i915 0000:00:02.0: product: Integrated gfx <7> [237.328820] i915 0000:00:02.0: source device information: PC General (0x9) <7> [237.328824] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.329203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe <7> [237.329673] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.330053] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [237.330057] i915 0000:00:02.0: empty frame <7> [237.330060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.330439] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset <7> [237.330885] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL C <7> [237.331380] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [237.331869] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0 <7> [237.332298] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz <7> [237.332770] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [237.333147] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz <7> [237.333521] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4 <7> [237.333938] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset] <7> [237.334341] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no <7> [237.334747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no <7> [237.335125] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no <7> [237.335502] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no <7> [237.335904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no <7> [237.336444] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Disable audio codec on [CRTC:78:pipe A] <7> [237.361844] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port C <7> [237.362781] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [237.375219] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10 <7> [237.379111] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time <7> [237.487143] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_C <7> [237.488183] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL C (active 0x1, on? 1) for [CRTC:78:pipe A] <7> [237.489696] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL C <7> [237.490109] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4 <7> [237.490549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [237.491134] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [237.491785] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2] <7> [237.492400] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-c <7> [237.493148] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A] <7> [237.494527] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [237.494643] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [237.495126] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz <7> [237.495663] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [237.495503] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13 <7> [237.497909] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [237.497809] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13 <7> [237.499059] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C] <7> [237.499397] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B] <7> [237.499459] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:176:HDMI-A-2] <7> [237.499695] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [237.500181] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [237.500566] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:121:pipe B] <7> [237.501213] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [237.501780] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [237.502193] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [237.502700] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL <7> [237.502719] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled <7> [237.502577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [237.503098] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d) <7> [237.503520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [237.504107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [237.504501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [237.505000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [237.505384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [237.505918] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [237.506347] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [237.506870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [237.507259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [237.507722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [237.508104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [237.508484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [237.509002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [237.509480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [237.510047] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [237.510501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [237.511050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [237.511465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [237.511996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [237.512384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [237.512883] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [237.513284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [237.513846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [237.514244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [237.514752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [237.515134] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [237.515516] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [237.516009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [237.516481] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [237.517068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [237.517524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected no, found yes) <7> [237.518057] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [237.518473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500) <7> [237.518983] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500) <7> [237.519376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 0, found 222750) <7> [237.519891] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [237.520300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [237.520848] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe <7> [237.521232] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.521699] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.522091] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [237.522095] i915 0000:00:02.0: colorspace: RGB <7> [237.522099] i915 0000:00:02.0: scan mode: Underscan <7> [237.522103] i915 0000:00:02.0: colorimetry: No Data <7> [237.522106] i915 0000:00:02.0: picture aspect: No Data <7> [237.522109] i915 0000:00:02.0: active aspect: Same as Picture <7> [237.522112] i915 0000:00:02.0: itc: No Data <7> [237.522115] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [237.522119] i915 0000:00:02.0: quantization range: Full <7> [237.522122] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [237.522125] i915 0000:00:02.0: video code: 0 <7> [237.522128] i915 0000:00:02.0: ycc quantization range: Full <7> [237.522131] i915 0000:00:02.0: hdmi content type: Graphics <7> [237.522134] i915 0000:00:02.0: pixel repeat: 0 <7> [237.522137] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [237.522141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe <7> [237.522520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.523063] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.523451] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [237.523455] i915 0000:00:02.0: vendor: Intel <7> [237.523458] i915 0000:00:02.0: product: Integrated gfx <7> [237.523462] i915 0000:00:02.0: source device information: PC General (0x9) <7> [237.523465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe <7> [237.523942] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [237.524411] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [237.525017] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [237.525022] i915 0000:00:02.0: empty frame <7> [237.525028] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset <7> [237.525583] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2 <7> [237.526287] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988 <7> [237.526861] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32 <7> [237.527241] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79: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> [237.527726] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0 <7> [237.528113] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0 <7> [237.528500] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0 <7> [237.529042] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [237.529493] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz <7> [237.530062] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL C <7> [237.530457] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL C <7> [237.530943] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset] <7> [237.531339] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [237.531835] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0 <7> [237.532220] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [237.532869] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [237.533321] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [237.533849] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [237.534267] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [237.534800] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [237.535183] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [237.535192] i915 0000:00:02.0: colorspace: RGB <7> [237.535196] i915 0000:00:02.0: scan mode: Underscan <7> [237.535199] i915 0000:00:02.0: colorimetry: No Data <7> [237.535202] i915 0000:00:02.0: picture aspect: No Data <7> [237.535205] i915 0000:00:02.0: active aspect: Same as Picture <7> [237.535209] i915 0000:00:02.0: itc: No Data <7> [237.535212] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [237.535215] i915 0000:00:02.0: quantization range: Full <7> [237.535218] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [237.535221] i915 0000:00:02.0: video code: 0 <7> [237.535225] i915 0000:00:02.0: ycc quantization range: Full <7> [237.535228] i915 0000:00:02.0: hdmi content type: Graphics <7> [237.535231] i915 0000:00:02.0: pixel repeat: 0 <7> [237.535234] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [237.535238] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [237.535242] i915 0000:00:02.0: vendor: Intel <7> [237.535245] i915 0000:00:02.0: product: Integrated gfx <7> [237.535248] i915 0000:00:02.0: source device information: PC General (0x9) <7> [237.535252] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [237.535256] i915 0000:00:02.0: empty frame <7> [237.535259] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [237.535816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [237.536230] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [237.536785] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [237.537182] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [237.537561] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0 <7> [237.538069] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [237.538462] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [237.538941] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [237.539323] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [237.539791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [237.540185] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [237.540865] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0 <7> [237.541332] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0 <7> [237.541865] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [237.542274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [237.542780] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [237.543172] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [237.543551] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [237.544184] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d <7> [237.544704] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [237.545087] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [237.545464] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [237.545977] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [237.546382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [237.547044] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [237.547441] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [237.547923] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [237.548385] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [237.548911] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [237.549331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no <7> [237.549864] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no <7> [237.550245] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no <7> [237.550811] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no <7> [237.552059] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c <7> [237.552786] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B] <7> [237.553173] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C] <7> [237.553907] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x2, on? 0) for [CRTC:121:pipe B] <7> [237.554313] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C <7> [237.555083] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C <7> [237.555786] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B <7> [237.590005] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD <7> [237.606696] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000) <7> [237.607215] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N <7> [237.609144] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2] <7> [237.609996] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B] <6> [240.943489] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

Detail

Value

Duration

3.67 seconds

Hostname

shard-glk3

Igt-Version

IGT-Version: 2.4-g6b305d78c (x86_64) (Linux: 7.1.0-rc3-CI_DRM_18478-g161329a551bb+ x86_64)

Out

Starting dynamic subtest: B-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
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-HDMI-A2: FAIL (3.672s)

Err

Starting dynamic subtest: B-HDMI-A2
[240.601109] (kms_flip:2488) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[240.601215] (kms_flip:2488) CRITICAL: Failed assertion: end - start < 500
[240.601300] (kms_flip:2488) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
[238.582888] (kms_flip:2488) DEBUG: Vblank took 22us
[238.599775] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.778000
last_received_ts = 238.777542
last_seq = 4408
current_ts = 238.794678
current_received_ts = 238.794479
current_seq = 4409
count = 70
seq_step = 1
[238.599831] (kms_flip:2488) DEBUG: Vblank took 25us
[238.616421] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.794678
last_received_ts = 238.794479
last_seq = 4409
current_ts = 238.811325
current_received_ts = 238.811127
current_seq = 4410
count = 71
seq_step = 1
[238.616471] (kms_flip:2488) DEBUG: Vblank took 22us
[238.633196] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.811325
last_received_ts = 238.811127
last_seq = 4410
current_ts = 238.828003
current_received_ts = 238.827911
current_seq = 4411
count = 72
seq_step = 1
[238.633247] (kms_flip:2488) DEBUG: Vblank took 22us
[238.649811] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.828003
last_received_ts = 238.827911
last_seq = 4411
current_ts = 238.844666
current_received_ts = 238.844513
current_seq = 4412
count = 73
seq_step = 1
[238.649863] (kms_flip:2488) DEBUG: Vblank took 22us
[238.666121] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.844666
last_received_ts = 238.844513
last_seq = 4412
current_ts = 238.861328
current_received_ts = 238.860825
current_seq = 4413
count = 74
seq_step = 1
[238.666169] (kms_flip:2488) DEBUG: Vblank took 22us
[238.683240] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.861328
last_received_ts = 238.860825
last_seq = 4413
current_ts = 238.878006
current_received_ts = 238.877945
current_seq = 4414
count = 75
seq_step = 1
[238.683322] (kms_flip:2488) DEBUG: Vblank took 21us
[238.699755] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.878006
last_received_ts = 238.877945
last_seq = 4414
current_ts = 238.894669
current_received_ts = 238.894470
current_seq = 4415
count = 76
seq_step = 1
[238.699805] (kms_flip:2488) DEBUG: Vblank took 22us
[238.716428] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.894669
last_received_ts = 238.894470
last_seq = 4415
current_ts = 238.911331
current_received_ts = 238.911133
current_seq = 4416
count = 77
seq_step = 1
[238.716475] (kms_flip:2488) DEBUG: Vblank took 21us
[238.733204] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.911331
last_received_ts = 238.911133
last_seq = 4416
current_ts = 238.927994
current_received_ts = 238.927917
current_seq = 4417
count = 78
seq_step = 1
[238.733254] (kms_flip:2488) DEBUG: Vblank took 23us
[238.750141] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.927994
last_received_ts = 238.927917
last_seq = 4417
current_ts = 238.944656
current_received_ts = 238.944855
current_seq = 4418
count = 79
seq_step = 1
[238.750190] (kms_flip:2488) DEBUG: Vblank took 22us
[238.766154] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.944656
last_received_ts = 238.944855
last_seq = 4418
current_ts = 238.961334
current_received_ts = 238.960861
current_seq = 4419
count = 80
seq_step = 1
[238.766205] (kms_flip:2488) DEBUG: Vblank took 23us
[238.783330] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.961334
last_received_ts = 238.960861
last_seq = 4419
current_ts = 238.977997
current_received_ts = 238.978043
current_seq = 4420
count = 81
seq_step = 1
[238.783378] (kms_flip:2488) DEBUG: Vblank took 22us
[238.799754] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.977997
last_received_ts = 238.978043
last_seq = 4420
current_ts = 238.994675
current_received_ts = 238.994461
current_seq = 4421
count = 82
seq_step = 1
[238.800046] (kms_flip:2488) DEBUG: Vblank took 22us
[238.816478] (kms_flip:2488) DEBUG: name = flip
last_ts = 238.994675
last_received_ts = 238.994461
last_seq = 4421
current_ts = 239.011337
current_received_ts = 239.011185
current_seq = 4422
count = 83
seq_step = 1
[238.816542] (kms_flip:2488) DEBUG: Vblank took 24us
[238.833197] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.011337
last_received_ts = 239.011185
last_seq = 4422
current_ts = 239.028000
current_received_ts = 239.027908
current_seq = 4423
count = 84
seq_step = 1
[238.833246] (kms_flip:2488) DEBUG: Vblank took 22us
[238.850144] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.028000
last_received_ts = 239.027908
last_seq = 4423
current_ts = 239.044662
current_received_ts = 239.044861
current_seq = 4424
count = 85
seq_step = 1
[238.850194] (kms_flip:2488) DEBUG: Vblank took 24us
[238.866142] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.044662
last_received_ts = 239.044861
last_seq = 4424
current_ts = 239.061340
current_received_ts = 239.060852
current_seq = 4425
count = 86
seq_step = 1
[238.866188] (kms_flip:2488) DEBUG: Vblank took 22us
[238.882941] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.061340
last_received_ts = 239.060852
last_seq = 4425
current_ts = 239.077988
current_received_ts = 239.077652
current_seq = 4426
count = 87
seq_step = 1
[238.882996] (kms_flip:2488) DEBUG: Vblank took 25us
[238.900209] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.077988
last_received_ts = 239.077652
last_seq = 4426
current_ts = 239.094666
current_received_ts = 239.094910
current_seq = 4427
count = 88
seq_step = 1
[238.900308] (kms_flip:2488) DEBUG: Vblank took 68us
[238.916149] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.094666
last_received_ts = 239.094910
last_seq = 4427
current_ts = 239.111328
current_received_ts = 239.110855
current_seq = 4428
count = 89
seq_step = 1
[238.916198] (kms_flip:2488) DEBUG: Vblank took 23us
[238.932867] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.111328
last_received_ts = 239.110855
last_seq = 4428
current_ts = 239.128006
current_received_ts = 239.127579
current_seq = 4429
count = 90
seq_step = 1
[238.932916] (kms_flip:2488) DEBUG: Vblank took 23us
[238.949789] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.128006
last_received_ts = 239.127579
last_seq = 4429
current_ts = 239.144669
current_received_ts = 239.144501
current_seq = 4430
count = 91
seq_step = 1
[238.949839] (kms_flip:2488) DEBUG: Vblank took 23us
[238.966445] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.144669
last_received_ts = 239.144501
last_seq = 4430
current_ts = 239.161331
current_received_ts = 239.161148
current_seq = 4431
count = 92
seq_step = 1
[238.966492] (kms_flip:2488) DEBUG: Vblank took 22us
[238.982850] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.161331
last_received_ts = 239.161148
last_seq = 4431
current_ts = 239.177994
current_received_ts = 239.177567
current_seq = 4432
count = 93
seq_step = 1
[238.982900] (kms_flip:2488) DEBUG: Vblank took 23us
[238.999808] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.177994
last_received_ts = 239.177567
last_seq = 4432
current_ts = 239.194672
current_received_ts = 239.194519
current_seq = 4433
count = 94
seq_step = 1
[238.999855] (kms_flip:2488) DEBUG: Vblank took 22us
[239.016623] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.194672
last_received_ts = 239.194519
last_seq = 4433
current_ts = 239.211334
current_received_ts = 239.211334
current_seq = 4434
count = 95
seq_step = 1
[239.016672] (kms_flip:2488) DEBUG: Vblank took 23us
[239.032860] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.211334
last_received_ts = 239.211334
last_seq = 4434
current_ts = 239.227997
current_received_ts = 239.227570
current_seq = 4435
count = 96
seq_step = 1
[239.032911] (kms_flip:2488) DEBUG: Vblank took 23us
[239.049785] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.227997
last_received_ts = 239.227570
last_seq = 4435
current_ts = 239.244659
current_received_ts = 239.244492
current_seq = 4436
count = 97
seq_step = 1
[239.049837] (kms_flip:2488) DEBUG: Vblank took 22us
[239.066120] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.244659
last_received_ts = 239.244492
last_seq = 4436
current_ts = 239.261337
current_received_ts = 239.260834
current_seq = 4437
count = 98
seq_step = 1
[239.066166] (kms_flip:2488) DEBUG: Vblank took 21us
[239.083027] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.261337
last_received_ts = 239.260834
last_seq = 4437
current_ts = 239.278000
current_received_ts = 239.277740
current_seq = 4438
count = 99
seq_step = 1
[239.083072] (kms_flip:2488) DEBUG: Vblank took 21us
[239.099803] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.278000
last_received_ts = 239.277740
last_seq = 4438
current_ts = 239.294678
current_received_ts = 239.294510
current_seq = 4439
count = 100
seq_step = 1
[239.099883] (kms_flip:2488) DEBUG: Vblank took 23us
[239.116428] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.294678
last_received_ts = 239.294510
last_seq = 4439
current_ts = 239.311340
current_received_ts = 239.311142
current_seq = 4440
count = 101
seq_step = 1
[239.116477] (kms_flip:2488) DEBUG: Vblank took 22us
[239.132828] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.311340
last_received_ts = 239.311142
last_seq = 4440
current_ts = 239.328003
current_received_ts = 239.327530
current_seq = 4441
count = 102
seq_step = 1
[239.132880] (kms_flip:2488) DEBUG: Vblank took 23us
[239.149756] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.328003
last_received_ts = 239.327530
last_seq = 4441
current_ts = 239.344666
current_received_ts = 239.344467
current_seq = 4442
count = 103
seq_step = 1
[239.149810] (kms_flip:2488) DEBUG: Vblank took 25us
[239.166130] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.344666
last_received_ts = 239.344467
last_seq = 4442
current_ts = 239.361343
current_received_ts = 239.360840
current_seq = 4443
count = 104
seq_step = 1
[239.166180] (kms_flip:2488) DEBUG: Vblank took 23us
[239.182954] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.361343
last_received_ts = 239.360840
last_seq = 4443
current_ts = 239.378006
current_received_ts = 239.377670
current_seq = 4444
count = 105
seq_step = 1
[239.183005] (kms_flip:2488) DEBUG: Vblank took 24us
[239.199770] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.378006
last_received_ts = 239.377670
last_seq = 4444
current_ts = 239.394669
current_received_ts = 239.394485
current_seq = 4445
count = 106
seq_step = 1
[239.199821] (kms_flip:2488) DEBUG: Vblank took 23us
[239.216512] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.394669
last_received_ts = 239.394485
last_seq = 4445
current_ts = 239.411331
current_received_ts = 239.411224
current_seq = 4446
count = 107
seq_step = 1
[239.216566] (kms_flip:2488) DEBUG: Vblank took 25us
[239.233236] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.411331
last_received_ts = 239.411224
last_seq = 4446
current_ts = 239.427994
current_received_ts = 239.427948
current_seq = 4447
count = 108
seq_step = 1
[239.233329] (kms_flip:2488) DEBUG: Vblank took 23us
[239.250128] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.427994
last_received_ts = 239.427948
last_seq = 4447
current_ts = 239.444672
current_received_ts = 239.444839
current_seq = 4448
count = 109
seq_step = 1
[239.250178] (kms_flip:2488) DEBUG: Vblank took 22us
[239.266122] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.444672
last_received_ts = 239.444839
last_seq = 4448
current_ts = 239.461334
current_received_ts = 239.460831
current_seq = 4449
count = 110
seq_step = 1
[239.266168] (kms_flip:2488) DEBUG: Vblank took 22us
[239.282850] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.461334
last_received_ts = 239.460831
last_seq = 4449
current_ts = 239.478012
current_received_ts = 239.477554
current_seq = 4450
count = 111
seq_step = 1
[239.282901] (kms_flip:2488) DEBUG: Vblank took 24us
[239.299815] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.478012
last_received_ts = 239.477554
last_seq = 4450
current_ts = 239.494675
current_received_ts = 239.494522
current_seq = 4451
count = 112
seq_step = 1
[239.299868] (kms_flip:2488) DEBUG: Vblank took 24us
[239.316120] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.494675
last_received_ts = 239.494522
last_seq = 4451
current_ts = 239.511337
current_received_ts = 239.510834
current_seq = 4452
count = 113
seq_step = 1
[239.316166] (kms_flip:2488) DEBUG: Vblank took 22us
[239.332945] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.511337
last_received_ts = 239.510834
last_seq = 4452
current_ts = 239.528000
current_received_ts = 239.527664
current_seq = 4453
count = 114
seq_step = 1
[239.332992] (kms_flip:2488) DEBUG: Vblank took 22us
[239.349761] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.528000
last_received_ts = 239.527664
last_seq = 4453
current_ts = 239.544678
current_received_ts = 239.544464
current_seq = 4454
count = 115
seq_step = 1
[239.349813] (kms_flip:2488) DEBUG: Vblank took 23us
[239.366445] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.544678
last_received_ts = 239.544464
last_seq = 4454
current_ts = 239.561325
current_received_ts = 239.561157
current_seq = 4455
count = 116
seq_step = 1
[239.366496] (kms_flip:2488) DEBUG: Vblank took 23us
[239.382784] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.561325
last_received_ts = 239.561157
last_seq = 4455
current_ts = 239.577988
current_received_ts = 239.577499
current_seq = 4456
count = 117
seq_step = 1
[239.382837] (kms_flip:2488) DEBUG: Vblank took 24us
[239.399936] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.577988
last_received_ts = 239.577499
last_seq = 4456
current_ts = 239.594666
current_received_ts = 239.594650
current_seq = 4457
count = 118
seq_step = 1
[239.399982] (kms_flip:2488) DEBUG: Vblank took 22us
[239.416519] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.594666
last_received_ts = 239.594650
last_seq = 4457
current_ts = 239.611328
current_received_ts = 239.611237
current_seq = 4458
count = 119
seq_step = 1
[239.416594] (kms_flip:2488) DEBUG: Vblank took 23us
[239.432856] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.611328
last_received_ts = 239.611237
last_seq = 4458
current_ts = 239.628006
current_received_ts = 239.627563
current_seq = 4459
count = 120
seq_step = 1
[239.432904] (kms_flip:2488) DEBUG: Vblank took 23us
[239.449660] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.628006
last_received_ts = 239.627563
last_seq = 4459
current_ts = 239.644669
current_received_ts = 239.644363
current_seq = 4460
count = 121
seq_step = 1
[239.449707] (kms_flip:2488) DEBUG: Vblank took 23us
[239.466907] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.644669
last_received_ts = 239.644363
last_seq = 4460
current_ts = 239.661331
current_received_ts = 239.661621
current_seq = 4461
count = 122
seq_step = 1
[239.466952] (kms_flip:2488) DEBUG: Vblank took 22us
[239.483321] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.661331
last_received_ts = 239.661621
last_seq = 4461
current_ts = 239.678009
current_received_ts = 239.677979
current_seq = 4462
count = 123
seq_step = 1
[239.483374] (kms_flip:2488) DEBUG: Vblank took 26us
[239.499814] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.678009
last_received_ts = 239.677979
last_seq = 4462
current_ts = 239.694672
current_received_ts = 239.694519
current_seq = 4463
count = 124
seq_step = 1
[239.499864] (kms_flip:2488) DEBUG: Vblank took 25us
[239.516464] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.694672
last_received_ts = 239.694519
last_seq = 4463
current_ts = 239.711334
current_received_ts = 239.711182
current_seq = 4464
count = 125
seq_step = 1
[239.516514] (kms_flip:2488) DEBUG: Vblank took 23us
[239.532833] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.711334
last_received_ts = 239.711182
last_seq = 4464
current_ts = 239.727997
current_received_ts = 239.727539
current_seq = 4465
count = 126
seq_step = 1
[239.532885] (kms_flip:2488) DEBUG: Vblank took 24us
[239.549958] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.727997
last_received_ts = 239.727539
last_seq = 4465
current_ts = 239.744675
current_received_ts = 239.744675
current_seq = 4466
count = 127
seq_step = 1
[239.550003] (kms_flip:2488) DEBUG: Vblank took 22us
[239.566468] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.744675
last_received_ts = 239.744675
last_seq = 4466
current_ts = 239.761337
current_received_ts = 239.761185
current_seq = 4467
count = 128
seq_step = 1
[239.566519] (kms_flip:2488) DEBUG: Vblank took 23us
[239.583195] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.761337
last_received_ts = 239.761185
last_seq = 4467
current_ts = 239.778000
current_received_ts = 239.777908
current_seq = 4468
count = 129
seq_step = 1
[239.583245] (kms_flip:2488) DEBUG: Vblank took 23us
[239.599805] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.778000
last_received_ts = 239.777908
last_seq = 4468
current_ts = 239.794662
current_received_ts = 239.794510
current_seq = 4469
count = 130
seq_step = 1
[239.599855] (kms_flip:2488) DEBUG: Vblank took 23us
[239.616842] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.794662
last_received_ts = 239.794510
last_seq = 4469
current_ts = 239.811340
current_received_ts = 239.811554
current_seq = 4470
count = 131
seq_step = 1
[239.616889] (kms_flip:2488) DEBUG: Vblank took 22us
[239.632879] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.811340
last_received_ts = 239.811554
last_seq = 4470
current_ts = 239.828003
current_received_ts = 239.827591
current_seq = 4471
count = 132
seq_step = 1
[239.632933] (kms_flip:2488) DEBUG: Vblank took 24us
[239.649809] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.828003
last_received_ts = 239.827591
last_seq = 4471
current_ts = 239.844666
current_received_ts = 239.844513
current_seq = 4472
count = 133
seq_step = 1
[239.649860] (kms_flip:2488) DEBUG: Vblank took 23us
[239.666148] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.844666
last_received_ts = 239.844513
last_seq = 4472
current_ts = 239.861343
current_received_ts = 239.860855
current_seq = 4473
count = 134
seq_step = 1
[239.666195] (kms_flip:2488) DEBUG: Vblank took 22us
[239.682941] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.861343
last_received_ts = 239.860855
last_seq = 4473
current_ts = 239.878006
current_received_ts = 239.877655
current_seq = 4474
count = 135
seq_step = 1
[239.682991] (kms_flip:2488) DEBUG: Vblank took 24us
[239.699877] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.878006
last_received_ts = 239.877655
last_seq = 4474
current_ts = 239.894669
current_received_ts = 239.894592
current_seq = 4475
count = 136
seq_step = 1
[239.699927] (kms_flip:2488) DEBUG: Vblank took 23us
[239.716450] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.894669
last_received_ts = 239.894592
last_seq = 4475
current_ts = 239.911331
current_received_ts = 239.911163
current_seq = 4476
count = 137
seq_step = 1
[239.716499] (kms_flip:2488) DEBUG: Vblank took 23us
[239.733212] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.911331
last_received_ts = 239.911163
last_seq = 4476
current_ts = 239.927994
current_received_ts = 239.927917
current_seq = 4477
count = 138
seq_step = 1
[239.733299] (kms_flip:2488) DEBUG: Vblank took 60us
[239.749804] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.927994
last_received_ts = 239.927917
last_seq = 4477
current_ts = 239.944656
current_received_ts = 239.944519
current_seq = 4478
count = 139
seq_step = 1
[239.749855] (kms_flip:2488) DEBUG: Vblank took 23us
[239.766234] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.944656
last_received_ts = 239.944519
last_seq = 4478
current_ts = 239.961334
current_received_ts = 239.960938
current_seq = 4479
count = 140
seq_step = 1
[239.766332] (kms_flip:2488) DEBUG: Vblank took 32us
[239.783017] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.961334
last_received_ts = 239.960938
last_seq = 4479
current_ts = 239.977997
current_received_ts = 239.977737
current_seq = 4480
count = 141
seq_step = 1
[239.783062] (kms_flip:2488) DEBUG: Vblank took 22us
[239.799859] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.977997
last_received_ts = 239.977737
last_seq = 4480
current_ts = 239.994659
current_received_ts = 239.994537
current_seq = 4481
count = 142
seq_step = 1
[239.799910] (kms_flip:2488) DEBUG: Vblank took 23us
[239.816485] (kms_flip:2488) DEBUG: name = flip
last_ts = 239.994659
last_received_ts = 239.994537
last_seq = 4481
current_ts = 240.011337
current_received_ts = 240.011200
current_seq = 4482
count = 143
seq_step = 1
[239.816533] (kms_flip:2488) DEBUG: Vblank took 22us
[239.833175] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.011337
last_received_ts = 240.011200
last_seq = 4482
current_ts = 240.028000
current_received_ts = 240.027893
current_seq = 4483
count = 144
seq_step = 1
[239.833223] (kms_flip:2488) DEBUG: Vblank took 22us
[239.849819] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.028000
last_received_ts = 240.027893
last_seq = 4483
current_ts = 240.044678
current_received_ts = 240.044525
current_seq = 4484
count = 145
seq_step = 1
[239.849869] (kms_flip:2488) DEBUG: Vblank took 24us
[239.866072] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.044678
last_received_ts = 240.044525
last_seq = 4484
current_ts = 240.061340
current_received_ts = 240.060791
current_seq = 4485
count = 146
seq_step = 1
[239.866119] (kms_flip:2488) DEBUG: Vblank took 22us
[239.882844] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.061340
last_received_ts = 240.060791
last_seq = 4485
current_ts = 240.078003
current_received_ts = 240.077560
current_seq = 4486
count = 147
seq_step = 1
[239.882895] (kms_flip:2488) DEBUG: Vblank took 23us
[239.899790] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.078003
last_received_ts = 240.077560
last_seq = 4486
current_ts = 240.094681
current_received_ts = 240.094498
current_seq = 4487
count = 148
seq_step = 1
[239.899842] (kms_flip:2488) DEBUG: Vblank took 25us
[239.916438] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.094681
last_received_ts = 240.094498
last_seq = 4487
current_ts = 240.111328
current_received_ts = 240.111145
current_seq = 4488
count = 149
seq_step = 1
[239.916487] (kms_flip:2488) DEBUG: Vblank took 22us
[239.932796] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.111328
last_received_ts = 240.111145
last_seq = 4488
current_ts = 240.128006
current_received_ts = 240.127502
current_seq = 4489
count = 150
seq_step = 1
[239.932844] (kms_flip:2488) DEBUG: Vblank took 23us
[239.950210] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.128006
last_received_ts = 240.127502
last_seq = 4489
current_ts = 240.144669
current_received_ts = 240.144928
current_seq = 4490
count = 151
seq_step = 1
[239.950290] (kms_flip:2488) DEBUG: Vblank took 22us
[239.966456] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.144669
last_received_ts = 240.144928
last_seq = 4490
current_ts = 240.161331
current_received_ts = 240.161163
current_seq = 4491
count = 152
seq_step = 1
[239.966510] (kms_flip:2488) DEBUG: Vblank took 25us
[239.982833] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.161331
last_received_ts = 240.161163
last_seq = 4491
current_ts = 240.178009
current_received_ts = 240.177551
current_seq = 4492
count = 153
seq_step = 1
[239.982884] (kms_flip:2488) DEBUG: Vblank took 24us
[240.000243] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.178009
last_received_ts = 240.177551
last_seq = 4492
current_ts = 240.194656
current_received_ts = 240.194962
current_seq = 4493
count = 154
seq_step = 1
[240.000335] (kms_flip:2488) DEBUG: Vblank took 23us
[240.016150] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.194656
last_received_ts = 240.194962
last_seq = 4493
current_ts = 240.211334
current_received_ts = 240.210861
current_seq = 4494
count = 155
seq_step = 1
[240.016200] (kms_flip:2488) DEBUG: Vblank took 22us
[240.033256] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.211334
last_received_ts = 240.210861
last_seq = 4494
current_ts = 240.227997
current_received_ts = 240.227966
current_seq = 4495
count = 156
seq_step = 1
[240.033414] (kms_flip:2488) DEBUG: Vblank took 20us
[240.050048] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.227997
last_received_ts = 240.227966
last_seq = 4495
current_ts = 240.244659
current_received_ts = 240.244751
current_seq = 4496
count = 157
seq_step = 1
[240.050100] (kms_flip:2488) DEBUG: Vblank took 24us
[240.066409] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.244659
last_received_ts = 240.244751
last_seq = 4496
current_ts = 240.261337
current_received_ts = 240.261124
current_seq = 4497
count = 158
seq_step = 1
[240.066459] (kms_flip:2488) DEBUG: Vblank took 22us
[240.083241] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.261337
last_received_ts = 240.261124
last_seq = 4497
current_ts = 240.278000
current_received_ts = 240.277954
current_seq = 4498
count = 159
seq_step = 1
[240.083333] (kms_flip:2488) DEBUG: Vblank took 24us
[240.100154] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.278000
last_received_ts = 240.277954
last_seq = 4498
current_ts = 240.294662
current_received_ts = 240.294861
current_seq = 4499
count = 160
seq_step = 1
[240.100206] (kms_flip:2488) DEBUG: Vblank took 24us
[240.116535] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.294662
last_received_ts = 240.294861
last_seq = 4499
current_ts = 240.311340
current_received_ts = 240.311249
current_seq = 4500
count = 161
seq_step = 1
[240.116584] (kms_flip:2488) DEBUG: Vblank took 23us
[240.133026] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.311340
last_received_ts = 240.311249
last_seq = 4500
current_ts = 240.328003
current_received_ts = 240.327744
current_seq = 4501
count = 162
seq_step = 1
[240.133072] (kms_flip:2488) DEBUG: Vblank took 21us
[240.149818] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.328003
last_received_ts = 240.327744
last_seq = 4501
current_ts = 240.344666
current_received_ts = 240.344528
current_seq = 4502
count = 163
seq_step = 1
[240.149892] (kms_flip:2488) DEBUG: Vblank took 47us
[240.166455] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.344666
last_received_ts = 240.344528
last_seq = 4502
current_ts = 240.361328
current_received_ts = 240.361176
current_seq = 4503
count = 164
seq_step = 1
[240.166503] (kms_flip:2488) DEBUG: Vblank took 21us
[240.182790] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.361328
last_received_ts = 240.361176
last_seq = 4503
current_ts = 240.378006
current_received_ts = 240.377502
current_seq = 4504
count = 165
seq_step = 1
[240.182840] (kms_flip:2488) DEBUG: Vblank took 23us
[240.200220] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.378006
last_received_ts = 240.377502
last_seq = 4504
current_ts = 240.394669
current_received_ts = 240.394928
current_seq = 4505
count = 166
seq_step = 1
[240.200304] (kms_flip:2488) DEBUG: Vblank took 58us
[240.216429] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.394669
last_received_ts = 240.394928
last_seq = 4505
current_ts = 240.411331
current_received_ts = 240.411148
current_seq = 4506
count = 167
seq_step = 1
[240.216479] (kms_flip:2488) DEBUG: Vblank took 22us
[240.232825] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.411331
last_received_ts = 240.411148
last_seq = 4506
current_ts = 240.428009
current_received_ts = 240.427536
current_seq = 4507
count = 168
seq_step = 1
[240.232878] (kms_flip:2488) DEBUG: Vblank took 24us
[240.250155] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.428009
last_received_ts = 240.427536
last_seq = 4507
current_ts = 240.444672
current_received_ts = 240.444870
current_seq = 4508
count = 169
seq_step = 1
[240.250204] (kms_flip:2488) DEBUG: Vblank took 23us
[240.266077] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.444672
last_received_ts = 240.444870
last_seq = 4508
current_ts = 240.461334
current_received_ts = 240.460785
current_seq = 4509
count = 170
seq_step = 1
[240.266126] (kms_flip:2488) DEBUG: Vblank took 23us
[240.282838] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.461334
last_received_ts = 240.460785
last_seq = 4509
current_ts = 240.477997
current_received_ts = 240.477554
current_seq = 4510
count = 171
seq_step = 1
[240.282888] (kms_flip:2488) DEBUG: Vblank took 22us
[240.299747] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.477997
last_received_ts = 240.477554
last_seq = 4510
current_ts = 240.494675
current_received_ts = 240.494461
current_seq = 4511
count = 172
seq_step = 1
[240.299800] (kms_flip:2488) DEBUG: Vblank took 23us
[240.316421] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.494675
last_received_ts = 240.494461
last_seq = 4511
current_ts = 240.511337
current_received_ts = 240.511139
current_seq = 4512
count = 173
seq_step = 1
[240.316471] (kms_flip:2488) DEBUG: Vblank took 22us
[240.332819] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.511337
last_received_ts = 240.511139
last_seq = 4512
current_ts = 240.528000
current_received_ts = 240.527527
current_seq = 4513
count = 174
seq_step = 1
[240.332871] (kms_flip:2488) DEBUG: Vblank took 24us
[240.349812] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.528000
last_received_ts = 240.527527
last_seq = 4513
current_ts = 240.544662
current_received_ts = 240.544525
current_seq = 4514
count = 175
seq_step = 1
[240.349864] (kms_flip:2488) DEBUG: Vblank took 23us
[240.366838] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.544662
last_received_ts = 240.544525
last_seq = 4514
current_ts = 240.561325
current_received_ts = 240.561554
current_seq = 4515
count = 176
seq_step = 1
[240.366882] (kms_flip:2488) DEBUG: Vblank took 21us
[240.382850] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.561325
last_received_ts = 240.561554
last_seq = 4515
current_ts = 240.578003
current_received_ts = 240.577560
current_seq = 4516
count = 177
seq_step = 1
[240.382903] (kms_flip:2488) DEBUG: Vblank took 24us
[240.399841] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.578003
last_received_ts = 240.577560
last_seq = 4516
current_ts = 240.594666
current_received_ts = 240.594559
current_seq = 4517
count = 178
seq_step = 1
[240.399893] (kms_flip:2488) DEBUG: Vblank took 23us
[240.416417] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.594666
last_received_ts = 240.594559
last_seq = 4517
current_ts = 240.611343
current_received_ts = 240.611130
current_seq = 4518
count = 179
seq_step = 1
[240.416460] (kms_flip:2488) DEBUG: Vblank took 20us
[240.432828] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.611343
last_received_ts = 240.611130
last_seq = 4518
current_ts = 240.628006
current_received_ts = 240.627533
current_seq = 4519
count = 180
seq_step = 1
[240.432879] (kms_flip:2488) DEBUG: Vblank took 23us
[240.450126] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.628006
last_received_ts = 240.627533
last_seq = 4519
current_ts = 240.644669
current_received_ts = 240.644836
current_seq = 4520
count = 181
seq_step = 1
[240.450175] (kms_flip:2488) DEBUG: Vblank took 22us
[240.466153] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.644669
last_received_ts = 240.644836
last_seq = 4520
current_ts = 240.661346
current_received_ts = 240.660873
current_seq = 4521
count = 182
seq_step = 1
[240.466202] (kms_flip:2488) DEBUG: Vblank took 23us
[240.482954] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.661346
last_received_ts = 240.660873
last_seq = 4521
current_ts = 240.677994
current_received_ts = 240.677673
current_seq = 4522
count = 183
seq_step = 1
[240.483002] (kms_flip:2488) DEBUG: Vblank took 22us
[240.499871] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.677994
last_received_ts = 240.677673
last_seq = 4522
current_ts = 240.694672
current_received_ts = 240.694550
current_seq = 4523
count = 184
seq_step = 1
[240.499921] (kms_flip:2488) DEBUG: Vblank took 23us
[240.516447] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.694672
last_received_ts = 240.694550
last_seq = 4523
current_ts = 240.711334
current_received_ts = 240.711166
current_seq = 4524
count = 185
seq_step = 1
[240.516495] (kms_flip:2488) DEBUG: Vblank took 23us
[240.532838] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.711334
last_received_ts = 240.711166
last_seq = 4524
current_ts = 240.727997
current_received_ts = 240.727554
current_seq = 4525
count = 186
seq_step = 1
[240.532888] (kms_flip:2488) DEBUG: Vblank took 23us
[240.549798] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.727997
last_received_ts = 240.727554
last_seq = 4525
current_ts = 240.744675
current_received_ts = 240.744507
current_seq = 4526
count = 187
seq_step = 1
[240.549848] (kms_flip:2488) DEBUG: Vblank took 24us
[240.566165] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.744675
last_received_ts = 240.744507
last_seq = 4526
current_ts = 240.761337
current_received_ts = 240.760880
current_seq = 4527
count = 188
seq_step = 1
[240.566213] (kms_flip:2488) DEBUG: Vblank took 22us
[240.583044] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.761337
last_received_ts = 240.760880
last_seq = 4527
current_ts = 240.778000
current_received_ts = 240.777756
current_seq = 4528
count = 189
seq_step = 1
[240.583090] (kms_flip:2488) DEBUG: Vblank took 22us
[240.599815] (kms_flip:2488) DEBUG: name = flip
last_ts = 240.778000
last_received_ts = 240.777756
last_seq = 4528
current_ts = 240.794678
current_received_ts = 240.794525
current_seq = 4529
count = 190
seq_step = 1
[240.601098] (kms_flip:2488) DEBUG: Vblank took 1258us
[240.601109] (kms_flip:2488) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[240.601215] (kms_flip:2488) CRITICAL: Failed assertion: end - start < 500
[240.601300] (kms_flip:2488) CRITICAL: Last errno: 4, Interrupted system call
[240.608303] (kms_flip:2488) igt_core-INFO: Stack trace:
[240.617769] (kms_flip:2488) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[240.619614] (kms_flip:2488) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[240.619809] (kms_flip:2488) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[240.619883] (kms_flip:2488) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[240.619968] (kms_flip:2488) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[240.634630] (kms_flip:2488) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[240.636891] (kms_flip:2488) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[240.637495] (kms_flip:2488) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (3.672s)

Dmesg

<6> [237.268513] [IGT] kms_flip: starting dynamic subtest B-HDMI-A2

<7> [237.269997] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:180]

<7> [237.270426] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:182]

<7> [237.307987] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:78:pipe A]

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

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

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

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

<7> [237.310788] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in lane_lat_optim_mask (expected 0x0000000d, found 0x00000000)

<7> [237.311309] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)

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

<7> [237.312334] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)

<7> [237.312755] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)

<7> [237.313135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)

<7> [237.313551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)

<7> [237.313956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)

<7> [237.314335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)

<7> [237.314737] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)

<7> [237.315127] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)

<7> [237.315519] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1083, found 0)

<7> [237.316000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1088, found 0)

<7> [237.316388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)

<7> [237.316883] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)

<7> [237.317325] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)

<7> [237.317763] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)

<7> [237.318143] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)

<7> [237.318575] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)

<7> [237.318996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)

<7> [237.319378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)

<7> [237.319802] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)

<7> [237.320214] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)

<7> [237.320591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1083, found 0)

<7> [237.321003] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1088, found 0)

<7> [237.321406] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)

<7> [237.321813] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)

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

<7> [237.322570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)

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

<7> [237.323371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_hdmi_sink (expected yes, found no)

<7> [237.323790] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in has_infoframe (expected yes, found no)

<7> [237.324172] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in pipe_bpp (expected 36, found 0)

<7> [237.324574] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)

<7> [237.324981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)

<7> [237.325447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in port_clock (expected 222750, found 0)

<7> [237.325859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000071, found 0x00000000)

<7> [237.326259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000006, found 0x00000000)

<7> [237.326738] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in avi infoframe

<7> [237.327137] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.327516] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [237.327521] i915 0000:00:02.0: colorspace: RGB

<7> [237.327525] i915 0000:00:02.0: scan mode: Underscan

<7> [237.327528] i915 0000:00:02.0: colorimetry: No Data

<7> [237.327531] i915 0000:00:02.0: picture aspect: No Data

<7> [237.327534] i915 0000:00:02.0: active aspect: Same as Picture

<7> [237.327537] i915 0000:00:02.0: itc: No Data

<7> [237.327540] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [237.327543] i915 0000:00:02.0: quantization range: Full

<7> [237.327546] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [237.327549] i915 0000:00:02.0: video code: 0

<7> [237.327552] i915 0000:00:02.0: ycc quantization range: Full

<7> [237.327555] i915 0000:00:02.0: hdmi content type: Graphics

<7> [237.327558] i915 0000:00:02.0: pixel repeat: 0

<7> [237.327561] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [237.327565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.328008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in spd infoframe

<7> [237.328388] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.328808] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [237.328813] i915 0000:00:02.0: vendor: Intel

<7> [237.328816] i915 0000:00:02.0: product: Integrated gfx

<7> [237.328820] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [237.328824] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.329203] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:78:pipe A] fastset requirement not met in hdmi infoframe

<7> [237.329673] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.330053] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [237.330057] i915 0000:00:02.0: empty frame

<7> [237.330060] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.330439] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:78:pipe A] fastset requirement not met, forcing full modeset

<7> [237.330885] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:78:pipe A] releasing PORT PLL C

<7> [237.331380] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:78:pipe A] dbuf slices 0x1 -> 0x0, ddb (0 - 1020) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [237.331869] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:72:cursor A] ddb ( 988 - 1020) -> ( 0 - 0), size 32 -> 0

<7> [237.332298] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:78:pipe A] min cdclk: 192000 kHz -> 0 kHz

<7> [237.332770] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [237.333147] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 79200 kHz, actual 79200 kHz

<7> [237.333521] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 4, actual 4

<7> [237.333938] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:78:pipe A] enable: no [modeset]

<7> [237.334341] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:36:plane 1A] fb: [NOFB], visible: no

<7> [237.334747] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:45:plane 2A] fb: [NOFB], visible: no

<7> [237.335125] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:plane 3A] fb: [NOFB], visible: no

<7> [237.335502] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:63:plane 4A] fb: [NOFB], visible: no

<7> [237.335904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:72:cursor A] fb: [NOFB], visible: no

<7> [237.336444] i915 0000:00:02.0: [drm:intel_audio_codec_disable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Disable audio codec on [CRTC:78:pipe A]

<7> [237.361844] i915 0000:00:02.0: [drm:intel_audio_component_get_eld [i915]] Not valid for port C

<7> [237.362781] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A

<7> [237.375219] i915 0000:00:02.0: [drm:intel_audio_component_get_power [i915]] restored AUD_FREQ_CNTRL to 0x10

<7> [237.379111] i915 0000:00:02.0: [drm:intel_ddi_disable_transcoder_func [i915]] Quirk Increase DDI disabled time

<7> [237.487143] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_C

<7> [237.488183] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PORT PLL C (active 0x1, on? 1) for [CRTC:78:pipe A]

<7> [237.489696] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PORT PLL C

<7> [237.490109] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 79200 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 4

<7> [237.490549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [237.491134] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [237.491785] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2]

<7> [237.492400] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling dpio-common-c

<7> [237.493148] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:78:pipe A]

<7> [237.494527] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [237.494643] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change

<7> [237.495126] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 316800 kHz, actual 316800 kHz

<7> [237.495663] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [237.495503] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 13, actual 13

<7> [237.497909] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [237.497809] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 316800 kHz, VCO 633600 kHz, ref 19200 kHz, bypass 19200 kHz, voltage level 13

<7> [237.499059] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:164:pipe C]

<7> [237.499397] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:121:pipe B]

<7> [237.499459] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:176:HDMI-A-2]

<7> [237.499695] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36)

<7> [237.500181] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [237.500566] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:175:DDI C/PHY C] [CRTC:121:pipe B]

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

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

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

<7> [237.502700] azx_init_pci: snd_hda_intel 0000:00:0e.0: Clearing TCSEL

<7> [237.502719] azx_init_pci: snd_hda_intel 0000:00:0e.0: SCH snoop: Enabled

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

<7> [237.503098] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in lane_lat_optim_mask (expected 0x00000000, found 0x0000000d)

<7> [237.503520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)

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

<7> [237.504501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [237.505000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [237.505384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [237.505918] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [237.506347] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [237.506870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [237.507259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [237.507722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [237.508104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083)

<7> [237.508484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088)

<7> [237.509002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [237.509480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [237.510047] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [237.510501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [237.511050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [237.511465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [237.511996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [237.512384] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [237.512883] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [237.513284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [237.513846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083)

<7> [237.514244] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088)

<7> [237.514752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [237.515134] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

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

<7> [237.516009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

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

<7> [237.517068] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_hdmi_sink (expected no, found yes)

<7> [237.517524] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in has_infoframe (expected no, found yes)

<7> [237.518057] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 36)

<7> [237.518473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)

<7> [237.518983] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)

<7> [237.519376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in port_clock (expected 0, found 222750)

<7> [237.519891] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071)

<7> [237.520300] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006)

<7> [237.520848] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in avi infoframe

<7> [237.521232] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.521699] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.522091] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [237.522095] i915 0000:00:02.0: colorspace: RGB

<7> [237.522099] i915 0000:00:02.0: scan mode: Underscan

<7> [237.522103] i915 0000:00:02.0: colorimetry: No Data

<7> [237.522106] i915 0000:00:02.0: picture aspect: No Data

<7> [237.522109] i915 0000:00:02.0: active aspect: Same as Picture

<7> [237.522112] i915 0000:00:02.0: itc: No Data

<7> [237.522115] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [237.522119] i915 0000:00:02.0: quantization range: Full

<7> [237.522122] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [237.522125] i915 0000:00:02.0: video code: 0

<7> [237.522128] i915 0000:00:02.0: ycc quantization range: Full

<7> [237.522131] i915 0000:00:02.0: hdmi content type: Graphics

<7> [237.522134] i915 0000:00:02.0: pixel repeat: 0

<7> [237.522137] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [237.522141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in spd infoframe

<7> [237.522520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.523063] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.523451] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [237.523455] i915 0000:00:02.0: vendor: Intel

<7> [237.523458] i915 0000:00:02.0: product: Integrated gfx

<7> [237.523462] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [237.523465] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:121:pipe B] fastset requirement not met in hdmi infoframe

<7> [237.523942] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [237.524411] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [237.525017] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [237.525022] i915 0000:00:02.0: empty frame

<7> [237.525028] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:121:pipe B] fastset requirement not met, forcing full modeset

<7> [237.525583] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:121:pipe B] dbuf slices 0x0 -> 0x1, ddb (0 - 0) -> (0 - 1020), active pipes 0x0 -> 0x2

<7> [237.526287] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:79:plane 1B] ddb ( 0 - 0) -> ( 0 - 988), size 0 -> 988

<7> [237.526861] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:115:cursor B] ddb ( 0 - 0) -> ( 988 - 1020), size 0 -> 32

<7> [237.527241] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79: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> [237.527726] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 1, 1, 2, 2, 2, 2, 2, 0, 0, 0

<7> [237.528113] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 16, 16, 33, 33, 33, 33, 33, 30, 0, 0

<7> [237.528500] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 17, 17, 17, 34, 34, 34, 34, 34, 31, 0, 0

<7> [237.529042] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:79:plane 1B] min_ddb_uv 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [237.529493] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:121:pipe B] min cdclk: 0 kHz -> 192000 kHz

<7> [237.530062] i915 0000:00:02.0: [drm:bxt_get_dpll [i915]] [CRTC:121:pipe B] using pre-allocated PORT PLL C

<7> [237.530457] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:121:pipe B] reserving PORT PLL C

<7> [237.530943] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:121:pipe B] enable: yes [modeset]

<7> [237.531339] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [237.531835] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 36, dithering: 0

<7> [237.532220] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

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

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

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

<7> [237.534267] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71

<7> [237.534800] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6

<7> [237.535183] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [237.535192] i915 0000:00:02.0: colorspace: RGB

<7> [237.535196] i915 0000:00:02.0: scan mode: Underscan

<7> [237.535199] i915 0000:00:02.0: colorimetry: No Data

<7> [237.535202] i915 0000:00:02.0: picture aspect: No Data

<7> [237.535205] i915 0000:00:02.0: active aspect: Same as Picture

<7> [237.535209] i915 0000:00:02.0: itc: No Data

<7> [237.535212] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [237.535215] i915 0000:00:02.0: quantization range: Full

<7> [237.535218] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [237.535221] i915 0000:00:02.0: video code: 0

<7> [237.535225] i915 0000:00:02.0: ycc quantization range: Full

<7> [237.535228] i915 0000:00:02.0: hdmi content type: Graphics

<7> [237.535231] i915 0000:00:02.0: pixel repeat: 0

<7> [237.535234] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [237.535238] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [237.535242] i915 0000:00:02.0: vendor: Intel

<7> [237.535245] i915 0000:00:02.0: product: Integrated gfx

<7> [237.535248] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [237.535252] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [237.535256] i915 0000:00:02.0: empty frame

<7> [237.535259] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00

<7> [237.535816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00

<7> [237.536230] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2

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

<7> [237.537182] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0

<7> [237.537561] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0

<7> [237.538069] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [237.538462] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [237.538941] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [237.539323] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [237.539791] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9

<7> [237.540185] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [237.540865] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 222750, pixel rate 148500, min cdclk 192000, min voltage level 0

<7> [237.541332] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 59, ips linetime: 0

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

<7> [237.542274] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [237.544184] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: ebb0: 0x6200, ebb4: 0x2000,pll0: 0x21, pll1: 0x100, pll2: 0x1a6666, pll3: 0x10000, pll6: 0x30904, pll8: 0x8, pll9: 0xa, pll10: 0x8003c00, pcsdw12: 0x4d

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

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

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

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

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

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

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

<7> [237.547923] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:79:plane 1B] fb: [FB:180] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

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

<7> [237.548911] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [237.549331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:88:plane 2B] fb: [NOFB], visible: no

<7> [237.549864] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:97:plane 3B] fb: [NOFB], visible: no

<7> [237.550245] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:106:plane 4B] fb: [NOFB], visible: no

<7> [237.550811] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:115:cursor B] fb: [NOFB], visible: no

<7> [237.552059] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling dpio-common-c

<7> [237.552786] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:165:DDI B/PHY B]

<7> [237.553173] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:175:DDI C/PHY C]

<7> [237.553907] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PORT PLL C (active 0x2, on? 0) for [CRTC:121:pipe B]

<7> [237.554313] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PORT PLL C

<7> [237.555083] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_C

<7> [237.555786] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B

<7> [237.590005] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:176:HDMI-A-2][ENCODER:175:DDI C/PHY C] Enable audio codec on [CRTC:121:pipe B], 32 bytes ELD

<7> [237.606696] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 148500 (0x00090000)

<7> [237.607215] i915 0000:00:02.0: [drm:hsw_audio_config_update [i915]] using automatic N

<7> [237.609144] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:176:HDMI-A-2]

<7> [237.609996] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:121:pipe B]

<6> [240.943489] [IGT] kms_flip: finished subtest B-HDMI-A2, FAIL

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