igt@kms_flip@flip-vs-expired-vblank-interruptible@a-hdmi-a2 on shard-rkl@CI_DRM

Detail	Value
Duration	5.71 seconds
Hostname	shard-rkl-3
Igt-Version	IGT-Version: 2.4-ga5c5d6558 (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18367-g81f5e3410e2a+ x86_64)
Out	Using IGT_SRANDOM=1777267191 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank-interruptible Starting dynamic subtest: A-HDMI-A2 1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 Stack trace: #0 ../lib/igt_core.c:2075 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-HDMI-A2: FAIL (5.714s)
Err	Starting subtest: flip-vs-expired-vblank-interruptible Starting dynamic subtest: A-HDMI-A2 (kms_flip:2115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2115) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2115) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest A-HDMI-A2 failed. ** DEBUG (kms_flip:2115) DEBUG: Vblank took 39us (kms_flip:2115) DEBUG: name = flip last_ts = 65.598244 last_received_ts = 65.597603 last_seq = 554 current_ts = 65.617218 current_received_ts = 65.616570 current_seq = 555 count = 168 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 65.617218 last_received_ts = 65.616570 last_seq = 555 current_ts = 65.636200 current_received_ts = 65.635574 current_seq = 556 count = 169 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.636200 last_received_ts = 65.635574 last_seq = 556 current_ts = 65.655182 current_received_ts = 65.654541 current_seq = 557 count = 170 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 43us (kms_flip:2115) DEBUG: name = flip last_ts = 65.655182 last_received_ts = 65.654541 last_seq = 557 current_ts = 65.674179 current_received_ts = 65.673531 current_seq = 558 count = 171 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 37us (kms_flip:2115) DEBUG: name = flip last_ts = 65.674179 last_received_ts = 65.673531 last_seq = 558 current_ts = 65.693146 current_received_ts = 65.692596 current_seq = 559 count = 172 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.693146 last_received_ts = 65.692596 last_seq = 559 current_ts = 65.712135 current_received_ts = 65.711487 current_seq = 560 count = 173 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 65.712135 last_received_ts = 65.711487 last_seq = 560 current_ts = 65.731133 current_received_ts = 65.730492 current_seq = 561 count = 174 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 38us (kms_flip:2115) DEBUG: name = flip last_ts = 65.731133 last_received_ts = 65.730492 last_seq = 561 current_ts = 65.750107 current_received_ts = 65.749451 current_seq = 562 count = 175 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 65.750107 last_received_ts = 65.749451 last_seq = 562 current_ts = 65.769089 current_received_ts = 65.768448 current_seq = 563 count = 176 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.769089 last_received_ts = 65.768448 last_seq = 563 current_ts = 65.788078 current_received_ts = 65.787460 current_seq = 564 count = 177 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 32us (kms_flip:2115) DEBUG: name = flip last_ts = 65.788078 last_received_ts = 65.787460 last_seq = 564 current_ts = 65.807060 current_received_ts = 65.806396 current_seq = 565 count = 178 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 36us (kms_flip:2115) DEBUG: name = flip last_ts = 65.807060 last_received_ts = 65.806396 last_seq = 565 current_ts = 65.826042 current_received_ts = 65.825378 current_seq = 566 count = 179 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 65.826042 last_received_ts = 65.825378 last_seq = 566 current_ts = 65.845024 current_received_ts = 65.844368 current_seq = 567 count = 180 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 65.845024 last_received_ts = 65.844368 last_seq = 567 current_ts = 65.864014 current_received_ts = 65.863419 current_seq = 568 count = 181 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.864014 last_received_ts = 65.863419 last_seq = 568 current_ts = 65.882988 current_received_ts = 65.882378 current_seq = 569 count = 182 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.882988 last_received_ts = 65.882378 last_seq = 569 current_ts = 65.901970 current_received_ts = 65.901314 current_seq = 570 count = 183 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.901970 last_received_ts = 65.901314 last_seq = 570 current_ts = 65.920952 current_received_ts = 65.920296 current_seq = 571 count = 184 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 40us (kms_flip:2115) DEBUG: name = flip last_ts = 65.920952 last_received_ts = 65.920296 last_seq = 571 current_ts = 65.939941 current_received_ts = 65.939278 current_seq = 572 count = 185 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 44us (kms_flip:2115) DEBUG: name = flip last_ts = 65.939941 last_received_ts = 65.939278 last_seq = 572 current_ts = 65.958916 current_received_ts = 65.958290 current_seq = 573 count = 186 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 39us (kms_flip:2115) DEBUG: name = flip last_ts = 65.958916 last_received_ts = 65.958290 last_seq = 573 current_ts = 65.977890 current_received_ts = 65.977303 current_seq = 574 count = 187 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 65.977890 last_received_ts = 65.977303 last_seq = 574 current_ts = 65.996880 current_received_ts = 65.996284 current_seq = 575 count = 188 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 32us (kms_flip:2115) DEBUG: name = flip last_ts = 65.996880 last_received_ts = 65.996284 last_seq = 575 current_ts = 66.015862 current_received_ts = 66.015205 current_seq = 576 count = 189 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 66.015862 last_received_ts = 66.015205 last_seq = 576 current_ts = 66.034843 current_received_ts = 66.034172 current_seq = 577 count = 190 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 66.034843 last_received_ts = 66.034172 last_seq = 577 current_ts = 66.053825 current_received_ts = 66.053246 current_seq = 578 count = 191 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 66.053825 last_received_ts = 66.053246 last_seq = 578 current_ts = 66.072800 current_received_ts = 66.072189 current_seq = 579 count = 192 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 53us (kms_flip:2115) DEBUG: name = flip last_ts = 66.072800 last_received_ts = 66.072189 last_seq = 579 current_ts = 66.091782 current_received_ts = 66.091156 current_seq = 580 count = 193 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 39us (kms_flip:2115) DEBUG: name = flip last_ts = 66.091782 last_received_ts = 66.091156 last_seq = 580 current_ts = 66.110779 current_received_ts = 66.110153 current_seq = 581 count = 194 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 37us (kms_flip:2115) DEBUG: name = flip last_ts = 66.110779 last_received_ts = 66.110153 last_seq = 581 current_ts = 66.129745 current_received_ts = 66.129135 current_seq = 582 count = 195 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 66.129745 last_received_ts = 66.129135 last_seq = 582 current_ts = 66.148743 current_received_ts = 66.148109 current_seq = 583 count = 196 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 36us (kms_flip:2115) DEBUG: name = flip last_ts = 66.148743 last_received_ts = 66.148109 last_seq = 583 current_ts = 66.167725 current_received_ts = 66.167091 current_seq = 584 count = 197 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 30us (kms_flip:2115) DEBUG: name = flip last_ts = 66.167725 last_received_ts = 66.167091 last_seq = 584 current_ts = 66.186699 current_received_ts = 66.186165 current_seq = 585 count = 198 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 33us (kms_flip:2115) DEBUG: name = flip last_ts = 66.186699 last_received_ts = 66.186165 last_seq = 585 current_ts = 66.205688 current_received_ts = 66.205078 current_seq = 586 count = 199 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 30us (kms_flip:2115) DEBUG: name = flip last_ts = 66.205688 last_received_ts = 66.205078 last_seq = 586 current_ts = 66.224670 current_received_ts = 66.224052 current_seq = 587 count = 200 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 66.224670 last_received_ts = 66.224052 last_seq = 587 current_ts = 66.243652 current_received_ts = 66.243042 current_seq = 588 count = 201 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 66.243652 last_received_ts = 66.243042 last_seq = 588 current_ts = 66.262634 current_received_ts = 66.261978 current_seq = 589 count = 202 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 44us (kms_flip:2115) DEBUG: name = flip last_ts = 66.262634 last_received_ts = 66.261978 last_seq = 589 current_ts = 66.281616 current_received_ts = 66.281059 current_seq = 590 count = 203 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 34us (kms_flip:2115) DEBUG: name = flip last_ts = 66.281616 last_received_ts = 66.281059 last_seq = 590 current_ts = 66.300598 current_received_ts = 66.299950 current_seq = 591 count = 204 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 69us (kms_flip:2115) DEBUG: name = flip last_ts = 66.300598 last_received_ts = 66.299950 last_seq = 591 current_ts = 66.319572 current_received_ts = 66.319099 current_seq = 592 count = 205 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 32us (kms_flip:2115) DEBUG: name = flip last_ts = 66.319572 last_received_ts = 66.319099 last_seq = 592 current_ts = 66.338554 current_received_ts = 66.337929 current_seq = 593 count = 206 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 34us (kms_flip:2115) DEBUG: name = flip last_ts = 66.338554 last_received_ts = 66.337929 last_seq = 593 current_ts = 66.357544 current_received_ts = 66.356888 current_seq = 594 count = 207 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 66.357544 last_received_ts = 66.356888 last_seq = 594 current_ts = 66.376526 current_received_ts = 66.375923 current_seq = 595 count = 208 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 61us (kms_flip:2115) DEBUG: name = flip last_ts = 66.376526 last_received_ts = 66.375923 last_seq = 595 current_ts = 66.395508 current_received_ts = 66.394875 current_seq = 596 count = 209 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 37us (kms_flip:2115) DEBUG: name = flip last_ts = 66.395508 last_received_ts = 66.394875 last_seq = 596 current_ts = 66.414490 current_received_ts = 66.413834 current_seq = 597 count = 210 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 66.414490 last_received_ts = 66.413834 last_seq = 597 current_ts = 66.433472 current_received_ts = 66.432816 current_seq = 598 count = 211 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 39us (kms_flip:2115) DEBUG: name = flip last_ts = 66.433472 last_received_ts = 66.432816 last_seq = 598 current_ts = 66.452446 current_received_ts = 66.451820 current_seq = 599 count = 212 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 39us (kms_flip:2115) DEBUG: name = flip last_ts = 66.452446 last_received_ts = 66.451820 last_seq = 599 current_ts = 66.471436 current_received_ts = 66.470779 current_seq = 600 count = 213 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 43us (kms_flip:2115) DEBUG: name = flip last_ts = 66.471436 last_received_ts = 66.470779 last_seq = 600 current_ts = 66.490425 current_received_ts = 66.489838 current_seq = 601 count = 214 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 66.490425 last_received_ts = 66.489838 last_seq = 601 current_ts = 66.509392 current_received_ts = 66.508766 current_seq = 602 count = 215 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 35us (kms_flip:2115) DEBUG: name = flip last_ts = 66.509392 last_received_ts = 66.508766 last_seq = 602 current_ts = 66.528374 current_received_ts = 66.527809 current_seq = 603 count = 216 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 30us (kms_flip:2115) DEBUG: name = flip last_ts = 66.528374 last_received_ts = 66.527809 last_seq = 603 current_ts = 66.547356 current_received_ts = 66.546730 current_seq = 604 count = 217 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 37us (kms_flip:2115) DEBUG: name = flip last_ts = 66.547356 last_received_ts = 66.546730 last_seq = 604 current_ts = 66.566338 current_received_ts = 66.565666 current_seq = 605 count = 218 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 41us (kms_flip:2115) DEBUG: name = flip last_ts = 66.566338 last_received_ts = 66.565666 last_seq = 605 current_ts = 66.585335 current_received_ts = 66.584732 current_seq = 606 count = 219 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 30us (kms_flip:2115) DEBUG: name = flip last_ts = 66.585335 last_received_ts = 66.584732 last_seq = 606 current_ts = 66.604309 current_received_ts = 66.603790 current_seq = 607 count = 220 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 31us (kms_flip:2115) DEBUG: name = flip last_ts = 66.604309 last_received_ts = 66.603790 last_seq = 607 current_ts = 66.623283 current_received_ts = 66.622643 current_seq = 608 count = 221 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 33us (kms_flip:2115) DEBUG: name = flip last_ts = 66.623283 last_received_ts = 66.622643 last_seq = 608 current_ts = 66.642273 current_received_ts = 66.641586 current_seq = 609 count = 222 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 15us (kms_flip:2115) DEBUG: name = flip last_ts = 66.642273 last_received_ts = 66.641586 last_seq = 609 current_ts = 66.661255 current_received_ts = 66.660576 current_seq = 610 count = 223 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 13us (kms_flip:2115) DEBUG: name = flip last_ts = 66.661255 last_received_ts = 66.660576 last_seq = 610 current_ts = 66.680237 current_received_ts = 66.679596 current_seq = 611 count = 224 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 66.680237 last_received_ts = 66.679596 last_seq = 611 current_ts = 66.699219 current_received_ts = 66.698532 current_seq = 612 count = 225 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.699219 last_received_ts = 66.698532 last_seq = 612 current_ts = 66.718193 current_received_ts = 66.717499 current_seq = 613 count = 226 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 66.718193 last_received_ts = 66.717499 last_seq = 613 current_ts = 66.737183 current_received_ts = 66.736481 current_seq = 614 count = 227 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.737183 last_received_ts = 66.736481 last_seq = 614 current_ts = 66.756165 current_received_ts = 66.755424 current_seq = 615 count = 228 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 9us (kms_flip:2115) DEBUG: name = flip last_ts = 66.756165 last_received_ts = 66.755424 last_seq = 615 current_ts = 66.775146 current_received_ts = 66.774437 current_seq = 616 count = 229 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 9us (kms_flip:2115) DEBUG: name = flip last_ts = 66.775146 last_received_ts = 66.774437 last_seq = 616 current_ts = 66.794128 current_received_ts = 66.793427 current_seq = 617 count = 230 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.794128 last_received_ts = 66.793427 last_seq = 617 current_ts = 66.813118 current_received_ts = 66.812416 current_seq = 618 count = 231 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.813118 last_received_ts = 66.812416 last_seq = 618 current_ts = 66.832100 current_received_ts = 66.831406 current_seq = 619 count = 232 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 66.832100 last_received_ts = 66.831406 last_seq = 619 current_ts = 66.851067 current_received_ts = 66.850372 current_seq = 620 count = 233 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 66.851067 last_received_ts = 66.850372 last_seq = 620 current_ts = 66.870056 current_received_ts = 66.869370 current_seq = 621 count = 234 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 66.870056 last_received_ts = 66.869370 last_seq = 621 current_ts = 66.889038 current_received_ts = 66.888329 current_seq = 622 count = 235 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.889038 last_received_ts = 66.888329 last_seq = 622 current_ts = 66.908020 current_received_ts = 66.907318 current_seq = 623 count = 236 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.908020 last_received_ts = 66.907318 last_seq = 623 current_ts = 66.927002 current_received_ts = 66.926285 current_seq = 624 count = 237 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 13us (kms_flip:2115) DEBUG: name = flip last_ts = 66.927002 last_received_ts = 66.926285 last_seq = 624 current_ts = 66.945976 current_received_ts = 66.945297 current_seq = 625 count = 238 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 13us (kms_flip:2115) DEBUG: name = flip last_ts = 66.945976 last_received_ts = 66.945297 last_seq = 625 current_ts = 66.964958 current_received_ts = 66.964264 current_seq = 626 count = 239 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 66.964958 last_received_ts = 66.964264 last_seq = 626 current_ts = 66.983940 current_received_ts = 66.983253 current_seq = 627 count = 240 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 15us (kms_flip:2115) DEBUG: name = flip last_ts = 66.983940 last_received_ts = 66.983253 last_seq = 627 current_ts = 67.002922 current_received_ts = 67.002228 current_seq = 628 count = 241 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 67.002922 last_received_ts = 67.002228 last_seq = 628 current_ts = 67.021904 current_received_ts = 67.021172 current_seq = 629 count = 242 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 9us (kms_flip:2115) DEBUG: name = flip last_ts = 67.021904 last_received_ts = 67.021172 last_seq = 629 current_ts = 67.040886 current_received_ts = 67.040161 current_seq = 630 count = 243 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.040886 last_received_ts = 67.040161 last_seq = 630 current_ts = 67.059860 current_received_ts = 67.059166 current_seq = 631 count = 244 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.059860 last_received_ts = 67.059166 last_seq = 631 current_ts = 67.078842 current_received_ts = 67.078178 current_seq = 632 count = 245 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 16us (kms_flip:2115) DEBUG: name = flip last_ts = 67.078842 last_received_ts = 67.078178 last_seq = 632 current_ts = 67.097824 current_received_ts = 67.097145 current_seq = 633 count = 246 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.097824 last_received_ts = 67.097145 last_seq = 633 current_ts = 67.116814 current_received_ts = 67.116081 current_seq = 634 count = 247 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 67.116814 last_received_ts = 67.116081 last_seq = 634 current_ts = 67.135788 current_received_ts = 67.135109 current_seq = 635 count = 248 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.135788 last_received_ts = 67.135109 last_seq = 635 current_ts = 67.154762 current_received_ts = 67.154114 current_seq = 636 count = 249 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.154762 last_received_ts = 67.154114 last_seq = 636 current_ts = 67.173744 current_received_ts = 67.173302 current_seq = 637 count = 250 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.173744 last_received_ts = 67.173302 last_seq = 637 current_ts = 67.192741 current_received_ts = 67.192039 current_seq = 638 count = 251 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.192741 last_received_ts = 67.192039 last_seq = 638 current_ts = 67.211716 current_received_ts = 67.211021 current_seq = 639 count = 252 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.211716 last_received_ts = 67.211021 last_seq = 639 current_ts = 67.230698 current_received_ts = 67.230011 current_seq = 640 count = 253 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.230698 last_received_ts = 67.230011 last_seq = 640 current_ts = 67.249672 current_received_ts = 67.249023 current_seq = 641 count = 254 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.249672 last_received_ts = 67.249023 last_seq = 641 current_ts = 67.268661 current_received_ts = 67.268013 current_seq = 642 count = 255 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.268661 last_received_ts = 67.268013 last_seq = 642 current_ts = 67.287643 current_received_ts = 67.286934 current_seq = 643 count = 256 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.287643 last_received_ts = 67.286934 last_seq = 643 current_ts = 67.306625 current_received_ts = 67.305916 current_seq = 644 count = 257 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.306625 last_received_ts = 67.305916 last_seq = 644 current_ts = 67.325607 current_received_ts = 67.324898 current_seq = 645 count = 258 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 14us (kms_flip:2115) DEBUG: name = flip last_ts = 67.325607 last_received_ts = 67.324898 last_seq = 645 current_ts = 67.344589 current_received_ts = 67.343880 current_seq = 646 count = 259 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 16us (kms_flip:2115) DEBUG: name = flip last_ts = 67.344589 last_received_ts = 67.343880 last_seq = 646 current_ts = 67.363564 current_received_ts = 67.362831 current_seq = 647 count = 260 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.363564 last_received_ts = 67.362831 last_seq = 647 current_ts = 67.382545 current_received_ts = 67.381828 current_seq = 648 count = 261 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 14us (kms_flip:2115) DEBUG: name = flip last_ts = 67.382545 last_received_ts = 67.381828 last_seq = 648 current_ts = 67.401527 current_received_ts = 67.400818 current_seq = 649 count = 262 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 22us (kms_flip:2115) DEBUG: name = flip last_ts = 67.401527 last_received_ts = 67.400818 last_seq = 649 current_ts = 67.420509 current_received_ts = 67.419800 current_seq = 650 count = 263 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.420509 last_received_ts = 67.419800 last_seq = 650 current_ts = 67.439491 current_received_ts = 67.438782 current_seq = 651 count = 264 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.439491 last_received_ts = 67.438782 last_seq = 651 current_ts = 67.458473 current_received_ts = 67.457771 current_seq = 652 count = 265 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.458473 last_received_ts = 67.457771 last_seq = 652 current_ts = 67.477448 current_received_ts = 67.476814 current_seq = 653 count = 266 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 24us (kms_flip:2115) DEBUG: name = flip last_ts = 67.477448 last_received_ts = 67.476814 last_seq = 653 current_ts = 67.496429 current_received_ts = 67.495728 current_seq = 654 count = 267 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.496429 last_received_ts = 67.495728 last_seq = 654 current_ts = 67.515419 current_received_ts = 67.514709 current_seq = 655 count = 268 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 18us (kms_flip:2115) DEBUG: name = flip last_ts = 67.515419 last_received_ts = 67.514709 last_seq = 655 current_ts = 67.534401 current_received_ts = 67.533699 current_seq = 656 count = 269 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 13us (kms_flip:2115) DEBUG: name = flip last_ts = 67.534401 last_received_ts = 67.533699 last_seq = 656 current_ts = 67.553375 current_received_ts = 67.552689 current_seq = 657 count = 270 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 14us (kms_flip:2115) DEBUG: name = flip last_ts = 67.553375 last_received_ts = 67.552689 last_seq = 657 current_ts = 67.572357 current_received_ts = 67.571693 current_seq = 658 count = 271 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.572357 last_received_ts = 67.571693 last_seq = 658 current_ts = 67.591339 current_received_ts = 67.590645 current_seq = 659 count = 272 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.591339 last_received_ts = 67.590645 last_seq = 659 current_ts = 67.610321 current_received_ts = 67.609627 current_seq = 660 count = 273 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.610321 last_received_ts = 67.609627 last_seq = 660 current_ts = 67.629303 current_received_ts = 67.628616 current_seq = 661 count = 274 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.629303 last_received_ts = 67.628616 last_seq = 661 current_ts = 67.648285 current_received_ts = 67.647591 current_seq = 662 count = 275 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.648285 last_received_ts = 67.647591 last_seq = 662 current_ts = 67.667259 current_received_ts = 67.666573 current_seq = 663 count = 276 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 12us (kms_flip:2115) DEBUG: name = flip last_ts = 67.667259 last_received_ts = 67.666573 last_seq = 663 current_ts = 67.686234 current_received_ts = 67.685547 current_seq = 664 count = 277 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.686234 last_received_ts = 67.685547 last_seq = 664 current_ts = 67.705223 current_received_ts = 67.704491 current_seq = 665 count = 278 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 14us (kms_flip:2115) DEBUG: name = flip last_ts = 67.705223 last_received_ts = 67.704491 last_seq = 665 current_ts = 67.724205 current_received_ts = 67.723473 current_seq = 666 count = 279 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 11us (kms_flip:2115) DEBUG: name = flip last_ts = 67.724205 last_received_ts = 67.723473 last_seq = 666 current_ts = 67.743187 current_received_ts = 67.742493 current_seq = 667 count = 280 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 10us (kms_flip:2115) DEBUG: name = flip last_ts = 67.743187 last_received_ts = 67.742493 last_seq = 667 current_ts = 67.762169 current_received_ts = 67.761482 current_seq = 668 count = 281 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 15us (kms_flip:2115) DEBUG: name = flip last_ts = 67.762169 last_received_ts = 67.761482 last_seq = 668 current_ts = 67.781136 current_received_ts = 67.780472 current_seq = 669 count = 282 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 27us (kms_flip:2115) DEBUG: name = flip last_ts = 67.781136 last_received_ts = 67.780472 last_seq = 669 current_ts = 67.800125 current_received_ts = 67.799469 current_seq = 670 count = 283 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 13us (kms_flip:2115) DEBUG: name = flip last_ts = 67.800125 last_received_ts = 67.799469 last_seq = 670 current_ts = 67.819107 current_received_ts = 67.818573 current_seq = 671 count = 284 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 14us (kms_flip:2115) DEBUG: name = flip last_ts = 67.819107 last_received_ts = 67.818573 last_seq = 671 current_ts = 67.838097 current_received_ts = 67.837440 current_seq = 672 count = 285 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 40us (kms_flip:2115) DEBUG: name = flip last_ts = 67.838097 last_received_ts = 67.837440 last_seq = 672 current_ts = 67.857079 current_received_ts = 67.856415 current_seq = 673 count = 286 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 37us (kms_flip:2115) DEBUG: name = flip last_ts = 67.857079 last_received_ts = 67.856415 last_seq = 673 current_ts = 67.876045 current_received_ts = 67.875427 current_seq = 674 count = 287 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 29us (kms_flip:2115) DEBUG: name = flip last_ts = 67.876045 last_received_ts = 67.875427 last_seq = 674 current_ts = 67.895035 current_received_ts = 67.894371 current_seq = 675 count = 288 seq_step = 1 (kms_flip:2115) DEBUG: Vblank took 727us (kms_flip:2115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: (kms_flip:2115) CRITICAL: Failed assertion: end - start < 500 (kms_flip:2115) CRITICAL: Last errno: 4, Interrupted system call (kms_flip:2115) igt_core-INFO: Stack trace: (kms_flip:2115) igt_core-INFO: #0 ../lib/igt_core.c:2075 __igt_fail_assert() (kms_flip:2115) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() (kms_flip:2115) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() (kms_flip:2115) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() (kms_flip:2115) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() (kms_flip:2115) igt_core-INFO: #5 [__libc_init_first+0x8a] (kms_flip:2115) igt_core-INFO: #6 [__libc_start_main+0x8b] (kms_flip:2115) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-HDMI-A2: FAIL (5.714s)
Dmesg	<6> [62.170077] Console: switching to colour dummy device 80x25 <6> [62.170143] [IGT] kms_flip: executing <7> [62.172468] i915 0000:00:02.0: [drm:i915_gem_open [i915]] <7> [62.173060] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc] <7> [62.173305] i915 0000:00:02.0: [drm:i915_gem_open [i915]] <7> [62.177572] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] <7> [62.177580] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:390:HDMI-A-1] <7> [62.181814] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] disconnected <7> [62.182366] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] <7> [62.182371] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:404:DP-1] <7> [62.186557] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] disconnected <7> [62.186801] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] <7> [62.186804] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:412:HDMI-A-3] <7> [62.191044] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] disconnected <7> [62.191336] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] <7> [62.191339] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:390:HDMI-A-1] <7> [62.195545] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] disconnected <7> [62.195557] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:400:HDMI-A-2] <7> [62.195561] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:400:HDMI-A-2] <7> [62.221231] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] Supported Monitor Refresh rate range is 0 Hz - 0 Hz <7> [62.221239] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] Assigning EDID-1.4 digital sink color depth as 8 bpc. <7> [62.221242] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] ELD monitor fitHeadless4k <7> [62.221245] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] ELD size 36, SAD count 0 <7> [62.221447] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK for addr: 0040 w(1) <7> [62.221570] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK on first message, retry <7> [62.221879] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK for addr: 0040 w(1) <7> [62.222011] i915 0000:00:02.0: [drm:drm_dp_dual_mode_detect [drm_display_helper]] DP dual mode HDMI ID: (err -6) <7> [62.222388] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1366x768": 216 268000 1366 1414 1446 1526 768 771 777 814 0x40 0x6 (CLOCK_HIGH) <7> [62.222394] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1920x1080i": 60 74250 1920 2008 2052 2200 1080 1084 1094 1125 0x40 0x15 (NO_INTERLACE) <7> [62.222399] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1920x1080i": 60 74176 1920 2008 2052 2200 1080 1084 1094 1125 0x40 0x15 (NO_INTERLACE) <7> [62.222405] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:400:HDMI-A-2] probed modes: <7> [62.222408] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 <7> [62.222412] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "4088x2304": 10 108000 4088 4152 4280 4536 2304 2305 2308 2340 0x40 0x5 <7> [62.222415] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "3840x2160": 15 128430 3840 3889 3921 4000 2160 2163 2169 2195 0x40 0xa <7> [62.222418] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 11 60000 2880 2888 2984 3040 1800 1802 1820 1845 0x40 0xa <7> [62.222421] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2560x1600": 13 60000 2560 2568 2664 2720 1600 1602 1620 1645 0x40 0xa <7> [62.222424] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2560x1440": 15 60000 2560 2568 2664 2720 1440 1442 1460 1485 0x40 0xa <7> [62.222428] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2048x1536": 17 60000 2048 2056 2152 2208 1536 1538 1556 1581 0x40 0xa <7> [62.222431] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1600x1200": 60 162000 1600 1664 1856 2160 1200 1201 1204 1250 0x40 0x5 <7> [62.222434] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1680x1050": 60 146250 1680 1784 1960 2240 1050 1053 1059 1089 0x40 0x6 <7> [62.222437] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1600x900": 60 108000 1600 1624 1704 1800 900 901 904 1000 0x40 0x5 <7> [62.222440] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x1024": 75 135000 1280 1296 1440 1688 1024 1025 1028 1066 0x40 0x5 <7> [62.222443] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1360x768": 60 84963 1366 1431 1567 1776 768 771 781 798 0x0 0x6 <7> [62.222446] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1360x768": 20 25190 1360 1368 1464 1520 768 770 788 813 0x40 0xa <7> [62.222449] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x800": 60 83500 1280 1352 1480 1680 800 803 809 831 0x40 0x6 <7> [62.222452] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1152x864": 75 108000 1152 1216 1344 1600 864 865 868 900 0x40 0x5 <7> [62.222455] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74250 1280 1390 1430 1650 720 725 730 750 0x40 0x5 <7> [62.222459] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74250 1280 1390 1430 1650 720 725 730 750 0x40 0x5 <7> [62.222462] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74176 1280 1390 1430 1650 720 725 730 750 0x40 0x5 <7> [62.222465] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x768": 75 78750 1024 1040 1136 1312 768 769 772 800 0x40 0x5 <7> [62.222468] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa <7> [62.222471] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1440x480": 60 54054 1440 1472 1596 1716 480 489 495 525 0x40 0xa <7> [62.222474] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1440x480": 60 54000 1440 1472 1596 1716 480 489 495 525 0x40 0xa <7> [62.222477] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x576": 60 46560 1024 1064 1160 1296 576 579 584 599 0x0 0x6 <7> [62.222480] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "832x624": 75 57284 832 864 928 1152 624 625 628 667 0x40 0xa <7> [62.222483] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "800x600": 75 49500 800 816 896 1056 600 601 604 625 0x40 0x5 <7> [62.222486] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "800x600": 60 40000 800 840 968 1056 600 601 605 628 0x40 0x5 <7> [62.222489] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 75 31500 640 656 720 840 480 481 484 500 0x40 0xa <7> [62.222492] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25200 640 656 752 800 480 490 492 525 0x40 0xa <7> [62.222496] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25175 640 656 752 800 480 490 492 525 0x40 0xa <7> [62.222499] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25175 640 656 752 800 480 490 492 525 0x40 0xa <7> [62.222502] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "720x400": 70 28320 720 738 846 900 400 412 414 449 0x40 0x6 <7> [62.222524] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] <7> [62.222528] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:404:DP-1] <7> [62.226722] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] disconnected <7> [62.226735] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] <7> [62.226738] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:412:HDMI-A-3] <7> [62.230926] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] disconnected <6> [62.234776] [IGT] kms_flip: starting subtest flip-vs-expired-vblank-interruptible <6> [62.236311] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2 <7> [62.236626] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:418] <7> [62.236710] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:419] <7> [62.281146] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [62.281381] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [62.281562] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [62.281702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [62.281839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [62.281993] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000) <7> [62.282130] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [62.282264] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0) <7> [62.282397] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2360, found 0) <7> [62.282531] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0) <7> [62.282662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2360, found 0) <7> [62.282795] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0) <7> [62.283050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2096, found 0) <7> [62.283182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0) <7> [62.283322] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0) <7> [62.283454] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0) <7> [62.283585] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0) <7> [62.283715] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0) <7> [62.283847] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0) <7> [62.283986] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0) <7> [62.284117] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2360, found 0) <7> [62.284248] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0) <7> [62.284379] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2360, found 0) <7> [62.284510] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0) <7> [62.284641] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2096, found 0) <7> [62.284774] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0) <7> [62.284905] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0) <7> [62.285086] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0) <7> [62.285218] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0) <7> [62.285350] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0) <7> [62.285481] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0) <7> [62.285612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [62.285742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0) <7> [62.285873] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0) <7> [62.286014] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [62.286145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 139929, found 0) <7> [62.286275] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 139929, found 0) <7> [62.286406] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 139929, found 0) <7> [62.286536] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [62.286668] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:151:pipe A] releasing DPLL 0 <7> [62.286826] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no <7> [62.286965] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [62.287117] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:35:plane 1A] ddb ( 0 - 2016) -> ( 0 - 0), size 2016 -> 0 <7> [62.287247] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (2016 - 2048) -> ( 0 - 0), size 32 -> 0 <7> [62.287376] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,twm, swm, stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [62.287505] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] lines 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [62.287634] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] blocks 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [62.287765] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] min_ddb 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [62.287913] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [62.288062] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 0 <7> [62.288196] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [62.288344] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 69965 kHz -> 0 kHz <7> [62.288492] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 8746 kHz -> 0 kHz <7> [62.288640] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Modeset required for cdclk change <7> [62.288771] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 180000 kHz, actual 180000 kHz <7> [62.288902] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0 <7> [62.289053] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:151:pipe A] enable: no [modeset] <7> [62.289186] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [62.289318] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [62.289451] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [62.289585] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [62.289720] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [62.289852] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [62.291322] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A <7> [62.310093] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1 <7> [62.310619] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [62.310894] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0 <7> [62.311151] i915 0000:00:02.0: [drm:__intel_fbc_disable [i915]] Disabling FBC on [PLANE:35:plane 1A] <7> [62.311385] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 180000 kHz, VCO 720000 kHz, ref 24000 kHz, bypass 12000 kHz, voltage level 0 <7> [62.311958] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:389:DDI B/PHY B] <7> [62.312167] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C] <7> [62.312394] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D] <7> [62.312609] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A] <7> [62.312808] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B] <7> [62.313025] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C] <7> [62.313228] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2] <7> [62.313563] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1 <7> [62.313821] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3 <7> [62.314300] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A] <7> [62.315584] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B] <7> [62.315730] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C] <7> [62.315854] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [62.315879] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:400:HDMI-A-2] <7> [62.315950] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:400:HDMI-A-2] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36) <7> [62.316113] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24) <7> [62.316256] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] hw max bpp: 24, pipe bpp: 24, dithering: 0 <7> [62.316412] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:399:DDI TC1/PHY C] [CRTC:151:pipe A] <7> [62.316558] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [62.316712] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [62.316870] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [62.317039] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [62.317191] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [62.317342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [62.317490] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [62.317640] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2360) <7> [62.317789] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [62.317952] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2360) <7> [62.318101] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [62.318250] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2096) <7> [62.318398] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [62.318544] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [62.318865] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084) <7> [62.319012] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089) <7> [62.319145] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [62.319277] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [62.319408] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [62.319539] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2360) <7> [62.319671] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [62.319801] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2360) <7> [62.319943] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [62.320074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2096) <7> [62.320206] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [62.320338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [62.320469] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084) <7> [62.320599] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089) <7> [62.320730] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [62.320861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [62.321004] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [62.321135] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [62.321268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4) <7> [62.321398] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 24) <7> [62.321529] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 139929) <7> [62.321661] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 139929) <7> [62.321793] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 139929) <7> [62.321930] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [62.322082] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no <7> [62.322215] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x1 <7> [62.322368] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 2016), size 0 -> 2016 <7> [62.322499] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (2016 - 2048), size 0 -> 32 <7> [62.322629] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5,wm6,wm7,twm, swm, stwm <7> [62.322760] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0 <7> [62.322904] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0 <7> [62.323039] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0 <7> [62.323184] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:151:pipe A] data rate 559716 num active planes 1 <7> [62.323320] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 560 <7> [62.323454] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1 <7> [62.323601] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 69965 kHz <7> [62.323748] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 0 kHz -> 8746 kHz <7> [62.323884] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:151:pipe A] allocated DPLL 0 <7> [62.324081] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:151:pipe A] reserving DPLL 0 <7> [62.324220] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:151:pipe A] enable: yes [modeset] <7> [62.324355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [62.324489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 24, dithering: 0 <7> [62.324626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [62.324762] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [62.324901] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [62.325035] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [62.325167] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0 <7> [62.325301] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2 <7> [62.325432] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [62.325563] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 42, guardband: 44 vsync start: 0, vsync end: 0 <7> [62.325697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1125, vmax vtotal: 1125 <7> [62.325828] 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> [62.325968] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 <7> [62.326100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 <7> [62.326232] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [62.326365] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 53 139929 1920 2008 2096 2360 1080 1084 1089 1125 0x40 0x5 <7> [62.326496] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5 <7> [62.326628] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 139929, pixel rate 139929, min cdclk 69965, min voltage level 0 <7> [62.326761] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 135, ips linetime: 0 <7> [62.326899] 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> [62.327031] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [62.327162] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [62.327294] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [62.327425] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [62.327556] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1a6655d, cfgcr1: 0xe84, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0 <7> [62.327687] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [62.327819] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [62.327961] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [62.328095] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.328226] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.328356] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.328485] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [62.328614] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [62.328745] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.328875] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.329018] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [62.329148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [62.329278] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:plane 1A] fb: [FB:418] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [62.329409] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [62.329539] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [62.329670] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [62.329802] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [62.329940] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [62.330071] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [62.330202] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [62.331639] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3 <7> [62.331796] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:389:DDI B/PHY B] <7> [62.331960] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C] <7> [62.332099] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D] <7> [62.332234] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A] <7> [62.332369] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B] <7> [62.332505] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C] <7> [62.332674] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3 <7> [62.332905] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [62.333044] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0 <7> [62.333335] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1 <7> [62.333509] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [62.333903] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 17694720 bytes of contiguous stolen space for FBC, limit: 1 <7> [62.334039] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:35:plane 1A] <7> [62.353172] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:400:HDMI-A-2] <7> [62.353417] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A] <6> [67.950115] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

Detail

Value

Duration

5.71 seconds

Hostname

shard-rkl-3

Igt-Version

IGT-Version: 2.4-ga5c5d6558 (x86_64) (Linux: 7.1.0-rc1-CI_DRM_18367-g81f5e3410e2a+ x86_64)

Out

Using IGT_SRANDOM=1777267191 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-HDMI-A2
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (5.714s)

Err

Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-HDMI-A2
(kms_flip:2115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2115) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2115) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:2115) DEBUG: Vblank took 39us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.598244
last_received_ts = 65.597603
last_seq = 554
current_ts = 65.617218
current_received_ts = 65.616570
current_seq = 555
count = 168
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.617218
last_received_ts = 65.616570
last_seq = 555
current_ts = 65.636200
current_received_ts = 65.635574
current_seq = 556
count = 169
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.636200
last_received_ts = 65.635574
last_seq = 556
current_ts = 65.655182
current_received_ts = 65.654541
current_seq = 557
count = 170
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 43us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.655182
last_received_ts = 65.654541
last_seq = 557
current_ts = 65.674179
current_received_ts = 65.673531
current_seq = 558
count = 171
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 37us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.674179
last_received_ts = 65.673531
last_seq = 558
current_ts = 65.693146
current_received_ts = 65.692596
current_seq = 559
count = 172
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.693146
last_received_ts = 65.692596
last_seq = 559
current_ts = 65.712135
current_received_ts = 65.711487
current_seq = 560
count = 173
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.712135
last_received_ts = 65.711487
last_seq = 560
current_ts = 65.731133
current_received_ts = 65.730492
current_seq = 561
count = 174
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 38us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.731133
last_received_ts = 65.730492
last_seq = 561
current_ts = 65.750107
current_received_ts = 65.749451
current_seq = 562
count = 175
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.750107
last_received_ts = 65.749451
last_seq = 562
current_ts = 65.769089
current_received_ts = 65.768448
current_seq = 563
count = 176
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.769089
last_received_ts = 65.768448
last_seq = 563
current_ts = 65.788078
current_received_ts = 65.787460
current_seq = 564
count = 177
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 32us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.788078
last_received_ts = 65.787460
last_seq = 564
current_ts = 65.807060
current_received_ts = 65.806396
current_seq = 565
count = 178
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 36us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.807060
last_received_ts = 65.806396
last_seq = 565
current_ts = 65.826042
current_received_ts = 65.825378
current_seq = 566
count = 179
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.826042
last_received_ts = 65.825378
last_seq = 566
current_ts = 65.845024
current_received_ts = 65.844368
current_seq = 567
count = 180
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.845024
last_received_ts = 65.844368
last_seq = 567
current_ts = 65.864014
current_received_ts = 65.863419
current_seq = 568
count = 181
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.864014
last_received_ts = 65.863419
last_seq = 568
current_ts = 65.882988
current_received_ts = 65.882378
current_seq = 569
count = 182
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.882988
last_received_ts = 65.882378
last_seq = 569
current_ts = 65.901970
current_received_ts = 65.901314
current_seq = 570
count = 183
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.901970
last_received_ts = 65.901314
last_seq = 570
current_ts = 65.920952
current_received_ts = 65.920296
current_seq = 571
count = 184
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 40us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.920952
last_received_ts = 65.920296
last_seq = 571
current_ts = 65.939941
current_received_ts = 65.939278
current_seq = 572
count = 185
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 44us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.939941
last_received_ts = 65.939278
last_seq = 572
current_ts = 65.958916
current_received_ts = 65.958290
current_seq = 573
count = 186
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 39us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.958916
last_received_ts = 65.958290
last_seq = 573
current_ts = 65.977890
current_received_ts = 65.977303
current_seq = 574
count = 187
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.977890
last_received_ts = 65.977303
last_seq = 574
current_ts = 65.996880
current_received_ts = 65.996284
current_seq = 575
count = 188
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 32us
(kms_flip:2115) DEBUG: name = flip
last_ts = 65.996880
last_received_ts = 65.996284
last_seq = 575
current_ts = 66.015862
current_received_ts = 66.015205
current_seq = 576
count = 189
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.015862
last_received_ts = 66.015205
last_seq = 576
current_ts = 66.034843
current_received_ts = 66.034172
current_seq = 577
count = 190
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.034843
last_received_ts = 66.034172
last_seq = 577
current_ts = 66.053825
current_received_ts = 66.053246
current_seq = 578
count = 191
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.053825
last_received_ts = 66.053246
last_seq = 578
current_ts = 66.072800
current_received_ts = 66.072189
current_seq = 579
count = 192
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 53us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.072800
last_received_ts = 66.072189
last_seq = 579
current_ts = 66.091782
current_received_ts = 66.091156
current_seq = 580
count = 193
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 39us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.091782
last_received_ts = 66.091156
last_seq = 580
current_ts = 66.110779
current_received_ts = 66.110153
current_seq = 581
count = 194
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 37us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.110779
last_received_ts = 66.110153
last_seq = 581
current_ts = 66.129745
current_received_ts = 66.129135
current_seq = 582
count = 195
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.129745
last_received_ts = 66.129135
last_seq = 582
current_ts = 66.148743
current_received_ts = 66.148109
current_seq = 583
count = 196
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 36us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.148743
last_received_ts = 66.148109
last_seq = 583
current_ts = 66.167725
current_received_ts = 66.167091
current_seq = 584
count = 197
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 30us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.167725
last_received_ts = 66.167091
last_seq = 584
current_ts = 66.186699
current_received_ts = 66.186165
current_seq = 585
count = 198
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 33us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.186699
last_received_ts = 66.186165
last_seq = 585
current_ts = 66.205688
current_received_ts = 66.205078
current_seq = 586
count = 199
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 30us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.205688
last_received_ts = 66.205078
last_seq = 586
current_ts = 66.224670
current_received_ts = 66.224052
current_seq = 587
count = 200
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.224670
last_received_ts = 66.224052
last_seq = 587
current_ts = 66.243652
current_received_ts = 66.243042
current_seq = 588
count = 201
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.243652
last_received_ts = 66.243042
last_seq = 588
current_ts = 66.262634
current_received_ts = 66.261978
current_seq = 589
count = 202
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 44us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.262634
last_received_ts = 66.261978
last_seq = 589
current_ts = 66.281616
current_received_ts = 66.281059
current_seq = 590
count = 203
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 34us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.281616
last_received_ts = 66.281059
last_seq = 590
current_ts = 66.300598
current_received_ts = 66.299950
current_seq = 591
count = 204
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 69us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.300598
last_received_ts = 66.299950
last_seq = 591
current_ts = 66.319572
current_received_ts = 66.319099
current_seq = 592
count = 205
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 32us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.319572
last_received_ts = 66.319099
last_seq = 592
current_ts = 66.338554
current_received_ts = 66.337929
current_seq = 593
count = 206
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 34us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.338554
last_received_ts = 66.337929
last_seq = 593
current_ts = 66.357544
current_received_ts = 66.356888
current_seq = 594
count = 207
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.357544
last_received_ts = 66.356888
last_seq = 594
current_ts = 66.376526
current_received_ts = 66.375923
current_seq = 595
count = 208
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 61us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.376526
last_received_ts = 66.375923
last_seq = 595
current_ts = 66.395508
current_received_ts = 66.394875
current_seq = 596
count = 209
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 37us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.395508
last_received_ts = 66.394875
last_seq = 596
current_ts = 66.414490
current_received_ts = 66.413834
current_seq = 597
count = 210
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.414490
last_received_ts = 66.413834
last_seq = 597
current_ts = 66.433472
current_received_ts = 66.432816
current_seq = 598
count = 211
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 39us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.433472
last_received_ts = 66.432816
last_seq = 598
current_ts = 66.452446
current_received_ts = 66.451820
current_seq = 599
count = 212
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 39us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.452446
last_received_ts = 66.451820
last_seq = 599
current_ts = 66.471436
current_received_ts = 66.470779
current_seq = 600
count = 213
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 43us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.471436
last_received_ts = 66.470779
last_seq = 600
current_ts = 66.490425
current_received_ts = 66.489838
current_seq = 601
count = 214
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.490425
last_received_ts = 66.489838
last_seq = 601
current_ts = 66.509392
current_received_ts = 66.508766
current_seq = 602
count = 215
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 35us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.509392
last_received_ts = 66.508766
last_seq = 602
current_ts = 66.528374
current_received_ts = 66.527809
current_seq = 603
count = 216
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 30us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.528374
last_received_ts = 66.527809
last_seq = 603
current_ts = 66.547356
current_received_ts = 66.546730
current_seq = 604
count = 217
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 37us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.547356
last_received_ts = 66.546730
last_seq = 604
current_ts = 66.566338
current_received_ts = 66.565666
current_seq = 605
count = 218
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 41us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.566338
last_received_ts = 66.565666
last_seq = 605
current_ts = 66.585335
current_received_ts = 66.584732
current_seq = 606
count = 219
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 30us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.585335
last_received_ts = 66.584732
last_seq = 606
current_ts = 66.604309
current_received_ts = 66.603790
current_seq = 607
count = 220
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 31us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.604309
last_received_ts = 66.603790
last_seq = 607
current_ts = 66.623283
current_received_ts = 66.622643
current_seq = 608
count = 221
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 33us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.623283
last_received_ts = 66.622643
last_seq = 608
current_ts = 66.642273
current_received_ts = 66.641586
current_seq = 609
count = 222
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 15us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.642273
last_received_ts = 66.641586
last_seq = 609
current_ts = 66.661255
current_received_ts = 66.660576
current_seq = 610
count = 223
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 13us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.661255
last_received_ts = 66.660576
last_seq = 610
current_ts = 66.680237
current_received_ts = 66.679596
current_seq = 611
count = 224
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.680237
last_received_ts = 66.679596
last_seq = 611
current_ts = 66.699219
current_received_ts = 66.698532
current_seq = 612
count = 225
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.699219
last_received_ts = 66.698532
last_seq = 612
current_ts = 66.718193
current_received_ts = 66.717499
current_seq = 613
count = 226
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.718193
last_received_ts = 66.717499
last_seq = 613
current_ts = 66.737183
current_received_ts = 66.736481
current_seq = 614
count = 227
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.737183
last_received_ts = 66.736481
last_seq = 614
current_ts = 66.756165
current_received_ts = 66.755424
current_seq = 615
count = 228
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 9us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.756165
last_received_ts = 66.755424
last_seq = 615
current_ts = 66.775146
current_received_ts = 66.774437
current_seq = 616
count = 229
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 9us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.775146
last_received_ts = 66.774437
last_seq = 616
current_ts = 66.794128
current_received_ts = 66.793427
current_seq = 617
count = 230
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.794128
last_received_ts = 66.793427
last_seq = 617
current_ts = 66.813118
current_received_ts = 66.812416
current_seq = 618
count = 231
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.813118
last_received_ts = 66.812416
last_seq = 618
current_ts = 66.832100
current_received_ts = 66.831406
current_seq = 619
count = 232
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.832100
last_received_ts = 66.831406
last_seq = 619
current_ts = 66.851067
current_received_ts = 66.850372
current_seq = 620
count = 233
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.851067
last_received_ts = 66.850372
last_seq = 620
current_ts = 66.870056
current_received_ts = 66.869370
current_seq = 621
count = 234
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.870056
last_received_ts = 66.869370
last_seq = 621
current_ts = 66.889038
current_received_ts = 66.888329
current_seq = 622
count = 235
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.889038
last_received_ts = 66.888329
last_seq = 622
current_ts = 66.908020
current_received_ts = 66.907318
current_seq = 623
count = 236
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.908020
last_received_ts = 66.907318
last_seq = 623
current_ts = 66.927002
current_received_ts = 66.926285
current_seq = 624
count = 237
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 13us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.927002
last_received_ts = 66.926285
last_seq = 624
current_ts = 66.945976
current_received_ts = 66.945297
current_seq = 625
count = 238
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 13us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.945976
last_received_ts = 66.945297
last_seq = 625
current_ts = 66.964958
current_received_ts = 66.964264
current_seq = 626
count = 239
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.964958
last_received_ts = 66.964264
last_seq = 626
current_ts = 66.983940
current_received_ts = 66.983253
current_seq = 627
count = 240
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 15us
(kms_flip:2115) DEBUG: name = flip
last_ts = 66.983940
last_received_ts = 66.983253
last_seq = 627
current_ts = 67.002922
current_received_ts = 67.002228
current_seq = 628
count = 241
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.002922
last_received_ts = 67.002228
last_seq = 628
current_ts = 67.021904
current_received_ts = 67.021172
current_seq = 629
count = 242
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 9us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.021904
last_received_ts = 67.021172
last_seq = 629
current_ts = 67.040886
current_received_ts = 67.040161
current_seq = 630
count = 243
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.040886
last_received_ts = 67.040161
last_seq = 630
current_ts = 67.059860
current_received_ts = 67.059166
current_seq = 631
count = 244
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.059860
last_received_ts = 67.059166
last_seq = 631
current_ts = 67.078842
current_received_ts = 67.078178
current_seq = 632
count = 245
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 16us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.078842
last_received_ts = 67.078178
last_seq = 632
current_ts = 67.097824
current_received_ts = 67.097145
current_seq = 633
count = 246
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.097824
last_received_ts = 67.097145
last_seq = 633
current_ts = 67.116814
current_received_ts = 67.116081
current_seq = 634
count = 247
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.116814
last_received_ts = 67.116081
last_seq = 634
current_ts = 67.135788
current_received_ts = 67.135109
current_seq = 635
count = 248
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.135788
last_received_ts = 67.135109
last_seq = 635
current_ts = 67.154762
current_received_ts = 67.154114
current_seq = 636
count = 249
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.154762
last_received_ts = 67.154114
last_seq = 636
current_ts = 67.173744
current_received_ts = 67.173302
current_seq = 637
count = 250
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.173744
last_received_ts = 67.173302
last_seq = 637
current_ts = 67.192741
current_received_ts = 67.192039
current_seq = 638
count = 251
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.192741
last_received_ts = 67.192039
last_seq = 638
current_ts = 67.211716
current_received_ts = 67.211021
current_seq = 639
count = 252
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.211716
last_received_ts = 67.211021
last_seq = 639
current_ts = 67.230698
current_received_ts = 67.230011
current_seq = 640
count = 253
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.230698
last_received_ts = 67.230011
last_seq = 640
current_ts = 67.249672
current_received_ts = 67.249023
current_seq = 641
count = 254
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.249672
last_received_ts = 67.249023
last_seq = 641
current_ts = 67.268661
current_received_ts = 67.268013
current_seq = 642
count = 255
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.268661
last_received_ts = 67.268013
last_seq = 642
current_ts = 67.287643
current_received_ts = 67.286934
current_seq = 643
count = 256
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.287643
last_received_ts = 67.286934
last_seq = 643
current_ts = 67.306625
current_received_ts = 67.305916
current_seq = 644
count = 257
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.306625
last_received_ts = 67.305916
last_seq = 644
current_ts = 67.325607
current_received_ts = 67.324898
current_seq = 645
count = 258
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 14us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.325607
last_received_ts = 67.324898
last_seq = 645
current_ts = 67.344589
current_received_ts = 67.343880
current_seq = 646
count = 259
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 16us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.344589
last_received_ts = 67.343880
last_seq = 646
current_ts = 67.363564
current_received_ts = 67.362831
current_seq = 647
count = 260
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.363564
last_received_ts = 67.362831
last_seq = 647
current_ts = 67.382545
current_received_ts = 67.381828
current_seq = 648
count = 261
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 14us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.382545
last_received_ts = 67.381828
last_seq = 648
current_ts = 67.401527
current_received_ts = 67.400818
current_seq = 649
count = 262
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 22us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.401527
last_received_ts = 67.400818
last_seq = 649
current_ts = 67.420509
current_received_ts = 67.419800
current_seq = 650
count = 263
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.420509
last_received_ts = 67.419800
last_seq = 650
current_ts = 67.439491
current_received_ts = 67.438782
current_seq = 651
count = 264
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.439491
last_received_ts = 67.438782
last_seq = 651
current_ts = 67.458473
current_received_ts = 67.457771
current_seq = 652
count = 265
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.458473
last_received_ts = 67.457771
last_seq = 652
current_ts = 67.477448
current_received_ts = 67.476814
current_seq = 653
count = 266
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 24us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.477448
last_received_ts = 67.476814
last_seq = 653
current_ts = 67.496429
current_received_ts = 67.495728
current_seq = 654
count = 267
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.496429
last_received_ts = 67.495728
last_seq = 654
current_ts = 67.515419
current_received_ts = 67.514709
current_seq = 655
count = 268
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 18us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.515419
last_received_ts = 67.514709
last_seq = 655
current_ts = 67.534401
current_received_ts = 67.533699
current_seq = 656
count = 269
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 13us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.534401
last_received_ts = 67.533699
last_seq = 656
current_ts = 67.553375
current_received_ts = 67.552689
current_seq = 657
count = 270
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 14us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.553375
last_received_ts = 67.552689
last_seq = 657
current_ts = 67.572357
current_received_ts = 67.571693
current_seq = 658
count = 271
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.572357
last_received_ts = 67.571693
last_seq = 658
current_ts = 67.591339
current_received_ts = 67.590645
current_seq = 659
count = 272
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.591339
last_received_ts = 67.590645
last_seq = 659
current_ts = 67.610321
current_received_ts = 67.609627
current_seq = 660
count = 273
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.610321
last_received_ts = 67.609627
last_seq = 660
current_ts = 67.629303
current_received_ts = 67.628616
current_seq = 661
count = 274
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.629303
last_received_ts = 67.628616
last_seq = 661
current_ts = 67.648285
current_received_ts = 67.647591
current_seq = 662
count = 275
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.648285
last_received_ts = 67.647591
last_seq = 662
current_ts = 67.667259
current_received_ts = 67.666573
current_seq = 663
count = 276
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 12us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.667259
last_received_ts = 67.666573
last_seq = 663
current_ts = 67.686234
current_received_ts = 67.685547
current_seq = 664
count = 277
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.686234
last_received_ts = 67.685547
last_seq = 664
current_ts = 67.705223
current_received_ts = 67.704491
current_seq = 665
count = 278
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 14us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.705223
last_received_ts = 67.704491
last_seq = 665
current_ts = 67.724205
current_received_ts = 67.723473
current_seq = 666
count = 279
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 11us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.724205
last_received_ts = 67.723473
last_seq = 666
current_ts = 67.743187
current_received_ts = 67.742493
current_seq = 667
count = 280
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 10us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.743187
last_received_ts = 67.742493
last_seq = 667
current_ts = 67.762169
current_received_ts = 67.761482
current_seq = 668
count = 281
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 15us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.762169
last_received_ts = 67.761482
last_seq = 668
current_ts = 67.781136
current_received_ts = 67.780472
current_seq = 669
count = 282
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 27us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.781136
last_received_ts = 67.780472
last_seq = 669
current_ts = 67.800125
current_received_ts = 67.799469
current_seq = 670
count = 283
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 13us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.800125
last_received_ts = 67.799469
last_seq = 670
current_ts = 67.819107
current_received_ts = 67.818573
current_seq = 671
count = 284
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 14us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.819107
last_received_ts = 67.818573
last_seq = 671
current_ts = 67.838097
current_received_ts = 67.837440
current_seq = 672
count = 285
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 40us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.838097
last_received_ts = 67.837440
last_seq = 672
current_ts = 67.857079
current_received_ts = 67.856415
current_seq = 673
count = 286
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 37us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.857079
last_received_ts = 67.856415
last_seq = 673
current_ts = 67.876045
current_received_ts = 67.875427
current_seq = 674
count = 287
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 29us
(kms_flip:2115) DEBUG: name = flip
last_ts = 67.876045
last_received_ts = 67.875427
last_seq = 674
current_ts = 67.895035
current_received_ts = 67.894371
current_seq = 675
count = 288
seq_step = 1
(kms_flip:2115) DEBUG: Vblank took 727us
(kms_flip:2115) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
(kms_flip:2115) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2115) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2115) igt_core-INFO: Stack trace:
(kms_flip:2115) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2115) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
(kms_flip:2115) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2115) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2115) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2115) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2115) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2115) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (5.714s)

Dmesg

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

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

<7> [62.172468] i915 0000:00:02.0: [drm:i915_gem_open [i915]]

<7> [62.173060] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc]

<7> [62.173305] i915 0000:00:02.0: [drm:i915_gem_open [i915]]

<7> [62.177572] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1]

<7> [62.177580] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:390:HDMI-A-1]

<7> [62.181814] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] disconnected

<7> [62.182366] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1]

<7> [62.182371] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:404:DP-1]

<7> [62.186557] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] disconnected

<7> [62.186801] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3]

<7> [62.186804] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:412:HDMI-A-3]

<7> [62.191044] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] disconnected

<7> [62.191336] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1]

<7> [62.191339] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:390:HDMI-A-1]

<7> [62.195545] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:390:HDMI-A-1] disconnected

<7> [62.195557] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:400:HDMI-A-2]

<7> [62.195561] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:400:HDMI-A-2]

<7> [62.221231] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] Supported Monitor Refresh rate range is 0 Hz - 0 Hz

<7> [62.221239] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] Assigning EDID-1.4 digital sink color depth as 8 bpc.

<7> [62.221242] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] ELD monitor fitHeadless4k

<7> [62.221245] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:400:HDMI-A-2] ELD size 36, SAD count 0

<7> [62.221447] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK for addr: 0040 w(1)

<7> [62.221570] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK on first message, retry

<7> [62.221879] i915 0000:00:02.0: [drm:do_gmbus_xfer [i915]] GMBUS [i915 gmbus tc1] NAK for addr: 0040 w(1)

<7> [62.222011] i915 0000:00:02.0: [drm:drm_dp_dual_mode_detect [drm_display_helper]] DP dual mode HDMI ID: (err -6)

<7> [62.222388] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1366x768": 216 268000 1366 1414 1446 1526 768 771 777 814 0x40 0x6 (CLOCK_HIGH)

<7> [62.222394] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1920x1080i": 60 74250 1920 2008 2052 2200 1080 1084 1094 1125 0x40 0x15 (NO_INTERLACE)

<7> [62.222399] i915 0000:00:02.0: [drm:drm_mode_prune_invalid] Rejected mode: "1920x1080i": 60 74176 1920 2008 2052 2200 1080 1084 1094 1125 0x40 0x15 (NO_INTERLACE)

<7> [62.222405] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:400:HDMI-A-2] probed modes:

<7> [62.222408] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5

<7> [62.222412] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "4088x2304": 10 108000 4088 4152 4280 4536 2304 2305 2308 2340 0x40 0x5

<7> [62.222415] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "3840x2160": 15 128430 3840 3889 3921 4000 2160 2163 2169 2195 0x40 0xa

<7> [62.222418] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 11 60000 2880 2888 2984 3040 1800 1802 1820 1845 0x40 0xa

<7> [62.222421] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2560x1600": 13 60000 2560 2568 2664 2720 1600 1602 1620 1645 0x40 0xa

<7> [62.222424] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2560x1440": 15 60000 2560 2568 2664 2720 1440 1442 1460 1485 0x40 0xa

<7> [62.222428] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2048x1536": 17 60000 2048 2056 2152 2208 1536 1538 1556 1581 0x40 0xa

<7> [62.222431] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1600x1200": 60 162000 1600 1664 1856 2160 1200 1201 1204 1250 0x40 0x5

<7> [62.222434] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1680x1050": 60 146250 1680 1784 1960 2240 1050 1053 1059 1089 0x40 0x6

<7> [62.222437] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1600x900": 60 108000 1600 1624 1704 1800 900 901 904 1000 0x40 0x5

<7> [62.222440] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x1024": 75 135000 1280 1296 1440 1688 1024 1025 1028 1066 0x40 0x5

<7> [62.222443] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1360x768": 60 84963 1366 1431 1567 1776 768 771 781 798 0x0 0x6

<7> [62.222446] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1360x768": 20 25190 1360 1368 1464 1520 768 770 788 813 0x40 0xa

<7> [62.222449] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x800": 60 83500 1280 1352 1480 1680 800 803 809 831 0x40 0x6

<7> [62.222452] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1152x864": 75 108000 1152 1216 1344 1600 864 865 868 900 0x40 0x5

<7> [62.222455] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74250 1280 1390 1430 1650 720 725 730 750 0x40 0x5

<7> [62.222459] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74250 1280 1390 1430 1650 720 725 730 750 0x40 0x5

<7> [62.222462] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1280x720": 60 74176 1280 1390 1430 1650 720 725 730 750 0x40 0x5

<7> [62.222465] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x768": 75 78750 1024 1040 1136 1312 768 769 772 800 0x40 0x5

<7> [62.222468] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa

<7> [62.222471] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1440x480": 60 54054 1440 1472 1596 1716 480 489 495 525 0x40 0xa

<7> [62.222474] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1440x480": 60 54000 1440 1472 1596 1716 480 489 495 525 0x40 0xa

<7> [62.222477] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "1024x576": 60 46560 1024 1064 1160 1296 576 579 584 599 0x0 0x6

<7> [62.222480] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "832x624": 75 57284 832 864 928 1152 624 625 628 667 0x40 0xa

<7> [62.222483] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "800x600": 75 49500 800 816 896 1056 600 601 604 625 0x40 0x5

<7> [62.222486] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "800x600": 60 40000 800 840 968 1056 600 601 605 628 0x40 0x5

<7> [62.222489] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 75 31500 640 656 720 840 480 481 484 500 0x40 0xa

<7> [62.222492] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25200 640 656 752 800 480 490 492 525 0x40 0xa

<7> [62.222496] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25175 640 656 752 800 480 490 492 525 0x40 0xa

<7> [62.222499] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "640x480": 60 25175 640 656 752 800 480 490 492 525 0x40 0xa

<7> [62.222502] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "720x400": 70 28320 720 738 846 900 400 412 414 449 0x40 0x6

<7> [62.222524] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1]

<7> [62.222528] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:404:DP-1]

<7> [62.226722] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:404:DP-1] disconnected

<7> [62.226735] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3]

<7> [62.226738] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:412:HDMI-A-3]

<7> [62.230926] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:412:HDMI-A-3] disconnected

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

<6> [62.236311] [IGT] kms_flip: starting dynamic subtest A-HDMI-A2

<7> [62.236626] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:418]

<7> [62.236710] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:419]

<7> [62.281146] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [62.286826] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0x3), mbus joined? no->no

<7> [62.286965] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [62.287117] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:35:plane 1A] ddb ( 0 - 2016) -> ( 0 - 0), size 2016 -> 0

<7> [62.287247] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb (2016 - 2048) -> ( 0 - 0), size 32 -> 0

<7> [62.287376] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm

<7> [62.287505] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] lines 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [62.287634] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] blocks 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [62.287765] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] min_ddb 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

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

<7> [62.288062] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 0

<7> [62.288196] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

<7> [62.288344] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 69965 kHz -> 0 kHz

<7> [62.288492] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 8746 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

<7> [62.310093] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_TC1

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

<7> [62.310894] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0

<7> [62.311151] i915 0000:00:02.0: [drm:__intel_fbc_disable [i915]] Disabling FBC on [PLANE:35:plane 1A]

<7> [62.311385] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 180000 kHz, VCO 720000 kHz, ref 24000 kHz, bypass 12000 kHz, voltage level 0

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

<7> [62.312167] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C]

<7> [62.312394] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D]

<7> [62.312609] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A]

<7> [62.312808] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B]

<7> [62.313025] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C]

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

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

<7> [62.313821] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_3

<7> [62.314300] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A]

<7> [62.315584] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]

<7> [62.315730] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]

<7> [62.315854] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

<7> [62.315950] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:400:HDMI-A-2] Limiting target display pipe bpp to 24 (EDID bpp 24, max requested bpp 36, max platform bpp 36)

<7> [62.316113] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)

<7> [62.316256] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:151:pipe A] hw max bpp: 24, pipe bpp: 24, dithering: 0

<7> [62.316412] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:399:DDI TC1/PHY C] [CRTC:151:pipe A]

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [62.322082] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0x3), mbus joined? no->no

<7> [62.322215] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x1

<7> [62.322368] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 2016), size 0 -> 2016

<7> [62.322499] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (2016 - 2048), size 0 -> 32

<7> [62.322629] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm

<7> [62.322760] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 2, 2, 2, 2, 5, 8, 9, 0, 0, 0

<7> [62.322904] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 16, 33, 33, 33, 33, 81, 129, 145, 30, 0, 0

<7> [62.323039] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 19, 38, 38, 38, 38, 91, 143, 161, 31, 0, 0

<7> [62.323184] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:151:pipe A] data rate 559716 num active planes 1

<7> [62.323320] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 16761 required 560

<7> [62.323454] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1

<7> [62.323601] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 69965 kHz

<7> [62.323748] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 0 kHz -> 8746 kHz

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

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

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

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

<7> [62.324489] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 24, dithering: 0

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

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

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

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

<7> [62.325167] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0

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

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

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

<7> [62.325697] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1081, vmax vblank: 1081, vmin vtotal: 1125, vmax vtotal: 1125

<7> [62.325828] 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> [62.325968] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5

<7> [62.326100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5

<7> [62.326232] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [62.326365] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 53 139929 1920 2008 2096 2360 1080 1084 1089 1125 0x40 0x5

<7> [62.326496] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=139929, hd=1920 hb=1920-2360 hs=2008-2096 ht=2360, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5

<7> [62.326628] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 139929, pixel rate 139929, min cdclk 69965, min voltage level 0

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

<7> [62.326899] 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> [62.327031] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

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

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

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

<7> [62.327556] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: cfgcr0: 0x1a6655d, cfgcr1: 0xe84, div0: 0x0, mg_refclkin_ctl: 0x0, hg_clktop2_coreclkctl1: 0x0, mg_clktop2_hsclkctl: 0x0, mg_pll_div0: 0x0, mg_pll_div2: 0x0, mg_pll_lf: 0x0, mg_pll_frac_lock: 0x0, mg_pll_ssc: 0x0, mg_pll_bias: 0x0, mg_pll_tdc_coldst_bias: 0x0

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [62.331639] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_3

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

<7> [62.331960] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:399:DDI TC1/PHY C]

<7> [62.332099] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:403:DDI TC2/PHY D]

<7> [62.332234] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:405:DP-MST A]

<7> [62.332369] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:406:DP-MST B]

<7> [62.332505] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:407:DP-MST C]

<7> [62.332674] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3

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

<7> [62.333044] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0

<7> [62.333335] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_TC1

<7> [62.333509] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A

<7> [62.333903] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] reserved 17694720 bytes of contiguous stolen space for FBC, limit: 1

<7> [62.334039] i915 0000:00:02.0: [drm:intel_fbc_update [i915]] Enabling FBC on [PLANE:35:plane 1A]

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

<7> [62.353417] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:151:pipe A]

<6> [67.950115] [IGT] kms_flip: finished subtest A-HDMI-A2, FAIL

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