Results for igt@kms_flip@flip-vs-absolute-wf_vblank@c-hdmi-a3

Result: Fail

integration-manifest git-log-oneline i915_display_info18 igt_runner18 runtimes18 results18.json results18-i915-load.json guc_logs18.tar i915_display_info_post_exec18 boot18 dmesg18

DetailValue
Duration 19.09 seconds
Hostname 
shard-dg2-5
Igt-Version 
IGT-Version: 2.4-g1c23bc1bd (x86_64) (Linux: 7.0.0-CI_DRM_18351-gec977e007a29+ x86_64)
Out 
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16667.7us +- 5.351us accuracy 0.10%
Event flip: expected 459, counted 450, passrate = 13.33%, encoder type 2
Event vblank: expected 459, counted 450, passrate = 11.11%, encoder type 2
Expected frametime: 16667us; measured 16829.3us +- 12.283us accuracy 0.22%
vblank interval differs from modeline! expected 16666.7us, measured 16829us +- 12.283us, difference 162.6us (13.2 sigma)
Event flip: expected 448, counted 450, passrate = 80.00%, encoder type 2
Event vblank: expected 448, counted 450, passrate = 77.78%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1071 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A3: FAIL (19.094s)
Err 
Starting dynamic subtest: C-HDMI-A3
(kms_flip:2258) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2258) CRITICAL: Failed assertion: !retried
Dynamic subtest C-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2258) DEBUG: name = vblank
last_ts = 259.799347
last_received_ts = 259.799072
last_seq = 478
current_ts = 259.968842
current_received_ts = 259.968628
current_seq = 488
count = 39
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 259.799347/478, current 259.968842/488: elapsed=169484.0us expected=166676.9us +- 833.4us, error 1.7%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 259.799347/478, current 259.968842/488: elapsed=169484.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = flip
last_ts = 259.816284
last_received_ts = 259.816101
last_seq = 479
current_ts = 259.985779
current_received_ts = 259.985596
current_seq = 489
count = 40
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 259.816284/479, current 259.985779/489: elapsed=169498.0us expected=166676.9us +- 833.4us, error 1.7%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 259.816284/479, current 259.985779/489: elapsed=169498.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 259.968842
last_received_ts = 259.968628
last_seq = 488
current_ts = 260.138306
current_received_ts = 260.138123
current_seq = 498
count = 40
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 259.968842/488, current 260.138306/498: elapsed=169464.0us expected=166676.9us +- 833.4us, error 1.7%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 259.968842/488, current 260.138306/498: elapsed=169464.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = flip
last_ts = 259.985779
last_received_ts = 259.985596
last_seq = 489
current_ts = 260.155212
current_received_ts = 260.155060
current_seq = 499
count = 41
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 259.985779/489, current 260.155212/499: elapsed=169426.0us expected=166676.9us +- 833.4us, error 1.6%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 259.985779/489, current 260.155212/499: elapsed=169426.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 260.138306
last_received_ts = 260.138123
last_seq = 498
current_ts = 260.307434
current_received_ts = 260.307251
current_seq = 508
count = 41
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 260.138306/498, current 260.307434/508: elapsed=169155.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 260.138306/498, current 260.307434/508: elapsed=169155.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = flip
last_ts = 260.155212
last_received_ts = 260.155060
last_seq = 499
current_ts = 260.324371
current_received_ts = 260.324188
current_seq = 509
count = 42
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 260.155212/499, current 260.324371/509: elapsed=169155.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 260.155212/499, current 260.324371/509: elapsed=169155.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 260.307434
last_received_ts = 260.307251
last_seq = 508
current_ts = 260.476593
current_received_ts = 260.476410
current_seq = 518
count = 42
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 260.307434/508, current 260.476593/518: elapsed=169150.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 260.307434/508, current 260.476593/518: elapsed=169150.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = flip
last_ts = 260.324371
last_received_ts = 260.324188
last_seq = 509
current_ts = 260.493530
current_received_ts = 260.493347
current_seq = 519
count = 43
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 260.324371/509, current 260.493530/519: elapsed=169153.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 260.324371/509, current 260.493530/519: elapsed=169153.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 260.476593
last_received_ts = 260.476410
last_seq = 518
current_ts = 260.645752
current_received_ts = 260.645538
current_seq = 528
count = 43
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 260.476593/518, current 260.645752/528: elapsed=169153.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 260.476593/518, current 260.645752/528: elapsed=169153.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = flip
last_ts = 260.493530
last_received_ts = 260.493347
last_seq = 519
current_ts = 260.662659
current_received_ts = 260.662476
current_seq = 529
count = 44
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 260.493530/519, current 260.662659/529: elapsed=169147.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 260.493530/519, current 260.662659/529: elapsed=169147.0us expected=166676.9us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 260.645752
last_received_ts = 260.645538
last_seq = 528
current_ts = 260.814911
current_received_ts = 260.814697
current_seq = 538
count = 44
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 260.645752/528, current 260.814911/538: elapsed=169157.0us expected=166676.9us +- 833.4us, error 1.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 260.645752/528, current 260.814911/538: elapsed=169157.0us expected=166676.9us
(kms_flip:2258) INFO: Event flip: expected 459, counted 450, passrate = 13.33%, encoder type 2
(kms_flip:2258) DEBUG: dropped frames, expected 459, counted 450, passrate = 13.33%, encoder type 2
(kms_flip:2258) INFO: Event vblank: expected 459, counted 450, passrate = 11.11%, encoder type 2
(kms_flip:2258) DEBUG: dropped frames, expected 459, counted 450, passrate = 11.11%, encoder type 2
(kms_flip:2258) DEBUG: Retrying without a hotplug event
(kms_flip:2258) DEBUG: No stale events found
(kms_flip:2258) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2258) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2258) INFO: Expected frametime: 16667us; measured 16829.3us +- 12.283us accuracy 0.22%
(kms_flip:2258) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16829us +- 12.283us, difference 162.6us (13.2 sigma)
(kms_flip:2258) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 264.243958
current_received_ts = 264.243683
current_seq = 560
count = 0
seq_step = 1
(kms_flip:2258) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 264.395325
current_received_ts = 264.395111
current_seq = 569
count = 0
seq_step = 10
(kms_flip:2258) DEBUG: name = flip
last_ts = 264.243958
last_received_ts = 264.243683
last_seq = 560
current_ts = 264.412140
current_received_ts = 264.411865
current_seq = 570
count = 1
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 264.243958/560, current 264.412140/570: elapsed=168161.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 264.395325
last_received_ts = 264.395111
last_seq = 569
current_ts = 264.563477
current_received_ts = 264.563263
current_seq = 579
count = 1
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 264.395325/569, current 264.563477/579: elapsed=168162.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = flip
last_ts = 264.412140
last_received_ts = 264.411865
last_seq = 570
current_ts = 264.580292
current_received_ts = 264.580109
current_seq = 580
count = 2
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 264.412140/570, current 264.580292/580: elapsed=168167.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 264.563477
last_received_ts = 264.563263
last_seq = 579
current_ts = 264.731628
current_received_ts = 264.731445
current_seq = 589
count = 2
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 264.563477/579, current 264.731628/589: elapsed=168150.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = flip
last_ts = 264.580292
last_received_ts = 264.580109
last_seq = 580
current_ts = 264.748444
current_received_ts = 264.748291
current_seq = 590
count = 3
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 264.580292/580, current 264.748444/590: elapsed=168153.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 264.731628
last_received_ts = 264.731445
last_seq = 589
current_ts = 264.899780
current_received_ts = 264.899597
current_seq = 599
count = 3
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 264.731628/589, current 264.899780/599: elapsed=168160.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = flip
last_ts = 264.748444
last_received_ts = 264.748291
last_seq = 590
current_ts = 264.916626
current_received_ts = 264.916260
current_seq = 600
count = 4
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 264.748444/590, current 264.916626/600: elapsed=168166.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 264.899780
last_received_ts = 264.899597
last_seq = 599
current_ts = 265.067963
current_received_ts = 265.067749
current_seq = 609
count = 4
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 264.899780/599, current 265.067963/609: elapsed=168156.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = flip
last_ts = 264.916626
last_received_ts = 264.916260
last_seq = 600
current_ts = 265.084778
current_received_ts = 265.084595
current_seq = 610
count = 5
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 264.916626/600, current 265.084778/610: elapsed=168165.0us expected=168292.5us +- 841.5us, error 0.1%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.067963
last_received_ts = 265.067749
last_seq = 609
current_ts = 265.235992
current_received_ts = 265.235779
current_seq = 619
count = 5
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.067963/609, current 265.235992/619: elapsed=168038.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.084778
last_received_ts = 265.084595
last_seq = 610
current_ts = 265.252777
current_received_ts = 265.252594
current_seq = 620
count = 6
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.084778/610, current 265.252777/620: elapsed=168013.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.235992
last_received_ts = 265.235779
last_seq = 619
current_ts = 265.403992
current_received_ts = 265.403778
current_seq = 629
count = 6
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.235992/619, current 265.403992/629: elapsed=167992.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.252777
last_received_ts = 265.252594
last_seq = 620
current_ts = 265.420776
current_received_ts = 265.420563
current_seq = 630
count = 7
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.252777/620, current 265.420776/630: elapsed=167986.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.403992
last_received_ts = 265.403778
last_seq = 629
current_ts = 265.571960
current_received_ts = 265.571777
current_seq = 639
count = 7
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.403992/629, current 265.571960/639: elapsed=167979.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.420776
last_received_ts = 265.420563
last_seq = 630
current_ts = 265.588776
current_received_ts = 265.588562
current_seq = 640
count = 8
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.420776/630, current 265.588776/640: elapsed=167984.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.571960
last_received_ts = 265.571777
last_seq = 639
current_ts = 265.739929
current_received_ts = 265.739746
current_seq = 649
count = 8
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.571960/639, current 265.739929/649: elapsed=167985.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.588776
last_received_ts = 265.588562
last_seq = 640
current_ts = 265.756744
current_received_ts = 265.756531
current_seq = 650
count = 9
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.588776/640, current 265.756744/650: elapsed=167982.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.739929
last_received_ts = 265.739746
last_seq = 649
current_ts = 265.907928
current_received_ts = 265.907715
current_seq = 659
count = 9
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.739929/649, current 265.907928/659: elapsed=167983.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.756744
last_received_ts = 265.756531
last_seq = 650
current_ts = 265.924744
current_received_ts = 265.924530
current_seq = 660
count = 10
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.756744/650, current 265.924744/660: elapsed=167986.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 265.907928
last_received_ts = 265.907715
last_seq = 659
current_ts = 266.075897
current_received_ts = 266.075714
current_seq = 669
count = 10
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 265.907928/659, current 266.075897/669: elapsed=167986.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = flip
last_ts = 265.924744
last_received_ts = 265.924530
last_seq = 660
current_ts = 266.092712
current_received_ts = 266.092499
current_seq = 670
count = 11
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 265.924744/660, current 266.092712/670: elapsed=167981.0us expected=168292.5us +- 841.5us, error 0.2%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.075897
last_received_ts = 266.075714
last_seq = 669
current_ts = 266.243774
current_received_ts = 266.243591
current_seq = 679
count = 11
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.075897/669, current 266.243774/679: elapsed=167866.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.092712
last_received_ts = 266.092499
last_seq = 670
current_ts = 266.260559
current_received_ts = 266.260345
current_seq = 680
count = 12
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.092712/670, current 266.260559/680: elapsed=167851.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.243774
last_received_ts = 266.243591
last_seq = 679
current_ts = 266.411621
current_received_ts = 266.411407
current_seq = 689
count = 12
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.243774/679, current 266.411621/689: elapsed=167830.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.260559
last_received_ts = 266.260345
last_seq = 680
current_ts = 266.428406
current_received_ts = 266.428223
current_seq = 690
count = 13
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.260559/680, current 266.428406/690: elapsed=167840.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.411621
last_received_ts = 266.411407
last_seq = 689
current_ts = 266.579437
current_received_ts = 266.579254
current_seq = 699
count = 13
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.411621/689, current 266.579437/699: elapsed=167843.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.428406
last_received_ts = 266.428223
last_seq = 690
current_ts = 266.596222
current_received_ts = 266.596069
current_seq = 700
count = 14
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.428406/690, current 266.596222/700: elapsed=167831.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.579437
last_received_ts = 266.579254
last_seq = 699
current_ts = 266.747284
current_received_ts = 266.747131
current_seq = 709
count = 14
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.579437/699, current 266.747284/709: elapsed=167818.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.596222
last_received_ts = 266.596069
last_seq = 700
current_ts = 266.764069
current_received_ts = 266.763885
current_seq = 710
count = 15
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.596222/700, current 266.764069/710: elapsed=167833.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.747284
last_received_ts = 266.747131
last_seq = 709
current_ts = 266.915100
current_received_ts = 266.914917
current_seq = 719
count = 15
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.747284/709, current 266.915100/719: elapsed=167831.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.764069
last_received_ts = 266.763885
last_seq = 710
current_ts = 266.931885
current_received_ts = 266.931702
current_seq = 720
count = 16
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.764069/710, current 266.931885/720: elapsed=167819.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 266.915100
last_received_ts = 266.914917
last_seq = 719
current_ts = 267.082947
current_received_ts = 267.082733
current_seq = 729
count = 16
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 266.915100/719, current 267.082947/729: elapsed=167844.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 266.931885
last_received_ts = 266.931702
last_seq = 720
current_ts = 267.099701
current_received_ts = 267.099548
current_seq = 730
count = 17
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 266.931885/720, current 267.099701/730: elapsed=167829.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.082947
last_received_ts = 267.082733
last_seq = 729
current_ts = 267.250671
current_received_ts = 267.250458
current_seq = 739
count = 17
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.082947/729, current 267.250671/739: elapsed=167723.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.099701
last_received_ts = 267.099548
last_seq = 730
current_ts = 267.267426
current_received_ts = 267.267242
current_seq = 740
count = 18
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.099701/730, current 267.267426/740: elapsed=167720.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.250671
last_received_ts = 267.250458
last_seq = 739
current_ts = 267.418365
current_received_ts = 267.418121
current_seq = 749
count = 18
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.250671/739, current 267.418365/749: elapsed=167691.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.267426
last_received_ts = 267.267242
last_seq = 740
current_ts = 267.435120
current_received_ts = 267.434937
current_seq = 750
count = 19
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.267426/740, current 267.435120/750: elapsed=167695.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.418365
last_received_ts = 267.418121
last_seq = 749
current_ts = 267.586029
current_received_ts = 267.585846
current_seq = 759
count = 19
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.418365/749, current 267.586029/759: elapsed=167686.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.435120
last_received_ts = 267.434937
last_seq = 750
current_ts = 267.602814
current_received_ts = 267.602386
current_seq = 760
count = 20
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.435120/750, current 267.602814/760: elapsed=167685.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.586029
last_received_ts = 267.585846
last_seq = 759
current_ts = 267.753754
current_received_ts = 267.753540
current_seq = 769
count = 20
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.586029/759, current 267.753754/769: elapsed=167696.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.602814
last_received_ts = 267.602386
last_seq = 760
current_ts = 267.770508
current_received_ts = 267.770325
current_seq = 770
count = 21
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.602814/760, current 267.770508/770: elapsed=167708.0us expected=168292.5us +- 841.5us, error 0.3%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.753754
last_received_ts = 267.753540
last_seq = 769
current_ts = 267.921448
current_received_ts = 267.921234
current_seq = 779
count = 21
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.753754/769, current 267.921448/779: elapsed=167697.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.770508
last_received_ts = 267.770325
last_seq = 770
current_ts = 267.938202
current_received_ts = 267.938080
current_seq = 780
count = 22
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.770508/770, current 267.938202/780: elapsed=167696.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 267.921448
last_received_ts = 267.921234
last_seq = 779
current_ts = 268.089142
current_received_ts = 268.088928
current_seq = 789
count = 22
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 267.921448/779, current 268.089142/789: elapsed=167696.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 267.938202
last_received_ts = 267.938080
last_seq = 780
current_ts = 268.105896
current_received_ts = 268.105743
current_seq = 790
count = 23
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 267.938202/780, current 268.105896/790: elapsed=167685.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.089142
last_received_ts = 268.088928
last_seq = 789
current_ts = 268.256744
current_received_ts = 268.256531
current_seq = 799
count = 23
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.089142/789, current 268.256744/799: elapsed=167610.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.105896
last_received_ts = 268.105743
last_seq = 790
current_ts = 268.273499
current_received_ts = 268.273315
current_seq = 800
count = 24
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.105896/790, current 268.273499/800: elapsed=167597.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.256744
last_received_ts = 268.256531
last_seq = 799
current_ts = 268.424316
current_received_ts = 268.424133
current_seq = 809
count = 24
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.256744/799, current 268.424316/809: elapsed=167565.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.273499
last_received_ts = 268.273315
last_seq = 800
current_ts = 268.441071
current_received_ts = 268.440887
current_seq = 810
count = 25
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.273499/800, current 268.441071/810: elapsed=167575.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.424316
last_received_ts = 268.424133
last_seq = 809
current_ts = 268.591888
current_received_ts = 268.591675
current_seq = 819
count = 25
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.424316/809, current 268.591888/819: elapsed=167578.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.441071
last_received_ts = 268.440887
last_seq = 810
current_ts = 268.608643
current_received_ts = 268.608459
current_seq = 820
count = 26
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.441071/810, current 268.608643/820: elapsed=167575.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.591888
last_received_ts = 268.591675
last_seq = 819
current_ts = 268.759460
current_received_ts = 268.759094
current_seq = 829
count = 26
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.591888/819, current 268.759460/829: elapsed=167582.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.608643
last_received_ts = 268.608459
last_seq = 820
current_ts = 268.776245
current_received_ts = 268.776093
current_seq = 830
count = 27
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.608643/820, current 268.776245/830: elapsed=167584.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.759460
last_received_ts = 268.759094
last_seq = 829
current_ts = 268.927063
current_received_ts = 268.926849
current_seq = 839
count = 27
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.759460/829, current 268.927063/839: elapsed=167584.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.776245
last_received_ts = 268.776093
last_seq = 830
current_ts = 268.943787
current_received_ts = 268.943604
current_seq = 840
count = 28
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.776245/830, current 268.943787/840: elapsed=167567.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 268.927063
last_received_ts = 268.926849
last_seq = 839
current_ts = 269.094635
current_received_ts = 269.094421
current_seq = 849
count = 28
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 268.927063/839, current 269.094635/849: elapsed=167581.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = flip
last_ts = 268.943787
last_received_ts = 268.943604
last_seq = 840
current_ts = 269.111389
current_received_ts = 269.111145
current_seq = 850
count = 29
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 268.943787/840, current 269.111389/850: elapsed=167580.0us expected=168292.5us +- 841.5us, error 0.4%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.094635
last_received_ts = 269.094421
last_seq = 849
current_ts = 269.262115
current_received_ts = 269.261841
current_seq = 859
count = 29
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.094635/849, current 269.262115/859: elapsed=167481.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.111389
last_received_ts = 269.111145
last_seq = 850
current_ts = 269.278870
current_received_ts = 269.278687
current_seq = 860
count = 30
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.111389/850, current 269.278870/860: elapsed=167489.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.262115
last_received_ts = 269.261841
last_seq = 859
current_ts = 269.429596
current_received_ts = 269.429382
current_seq = 869
count = 30
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.262115/859, current 269.429596/869: elapsed=167484.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.278870
last_received_ts = 269.278687
last_seq = 860
current_ts = 269.446320
current_received_ts = 269.445953
current_seq = 870
count = 31
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.278870/860, current 269.446320/870: elapsed=167462.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.429596
last_received_ts = 269.429382
last_seq = 869
current_ts = 269.597046
current_received_ts = 269.596619
current_seq = 879
count = 31
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.429596/869, current 269.597046/879: elapsed=167462.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.446320
last_received_ts = 269.445953
last_seq = 870
current_ts = 269.613831
current_received_ts = 269.613342
current_seq = 880
count = 32
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.446320/870, current 269.613831/880: elapsed=167487.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.597046
last_received_ts = 269.596619
last_seq = 879
current_ts = 269.764526
current_received_ts = 269.764252
current_seq = 889
count = 32
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.597046/879, current 269.764526/889: elapsed=167478.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.613831
last_received_ts = 269.613342
last_seq = 880
current_ts = 269.781281
current_received_ts = 269.780884
current_seq = 890
count = 33
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.613831/880, current 269.781281/890: elapsed=167476.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.764526
last_received_ts = 269.764252
last_seq = 889
current_ts = 269.932007
current_received_ts = 269.931793
current_seq = 899
count = 33
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.764526/889, current 269.932007/899: elapsed=167472.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.781281
last_received_ts = 269.780884
last_seq = 890
current_ts = 269.948761
current_received_ts = 269.948517
current_seq = 900
count = 34
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.781281/890, current 269.948761/900: elapsed=167478.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 269.932007
last_received_ts = 269.931793
last_seq = 899
current_ts = 270.099487
current_received_ts = 270.099274
current_seq = 909
count = 34
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 269.932007/899, current 270.099487/909: elapsed=167477.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = flip
last_ts = 269.948761
last_received_ts = 269.948517
last_seq = 900
current_ts = 270.116241
current_received_ts = 270.116058
current_seq = 910
count = 35
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 269.948761/900, current 270.116241/910: elapsed=167471.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.099487
last_received_ts = 270.099274
last_seq = 909
current_ts = 270.266876
current_received_ts = 270.266632
current_seq = 919
count = 35
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.099487/909, current 270.266876/919: elapsed=167392.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.099487/909, current 270.266876/919: elapsed=167392.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.116241
last_received_ts = 270.116058
last_seq = 910
current_ts = 270.283630
current_received_ts = 270.283386
current_seq = 920
count = 36
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.116241/910, current 270.283630/920: elapsed=167379.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.116241/910, current 270.283630/920: elapsed=167379.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.266876
last_received_ts = 270.266632
last_seq = 919
current_ts = 270.434265
current_received_ts = 270.434052
current_seq = 929
count = 36
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.266876/919, current 270.434265/929: elapsed=167396.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.266876/919, current 270.434265/929: elapsed=167396.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.283630
last_received_ts = 270.283386
last_seq = 920
current_ts = 270.451019
current_received_ts = 270.450775
current_seq = 930
count = 37
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.283630/920, current 270.451019/930: elapsed=167394.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.283630/920, current 270.451019/930: elapsed=167394.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.434265
last_received_ts = 270.434052
last_seq = 929
current_ts = 270.601654
current_received_ts = 270.601410
current_seq = 939
count = 37
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.434265/929, current 270.601654/939: elapsed=167374.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.434265/929, current 270.601654/939: elapsed=167374.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.451019
last_received_ts = 270.450775
last_seq = 930
current_ts = 270.618408
current_received_ts = 270.618164
current_seq = 940
count = 38
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.451019/930, current 270.618408/940: elapsed=167383.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.451019/930, current 270.618408/940: elapsed=167383.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.601654
last_received_ts = 270.601410
last_seq = 939
current_ts = 270.769043
current_received_ts = 270.768799
current_seq = 949
count = 38
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.601654/939, current 270.769043/949: elapsed=167386.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.601654/939, current 270.769043/949: elapsed=167386.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.618408
last_received_ts = 270.618164
last_seq = 940
current_ts = 270.785797
current_received_ts = 270.785553
current_seq = 950
count = 39
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.618408/940, current 270.785797/950: elapsed=167386.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.618408/940, current 270.785797/950: elapsed=167386.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.769043
last_received_ts = 270.768799
last_seq = 949
current_ts = 270.936432
current_received_ts = 270.936188
current_seq = 959
count = 39
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.769043/949, current 270.936432/959: elapsed=167384.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.769043/949, current 270.936432/959: elapsed=167384.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.785797
last_received_ts = 270.785553
last_seq = 950
current_ts = 270.953156
current_received_ts = 270.952942
current_seq = 960
count = 40
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.785797/950, current 270.953156/960: elapsed=167377.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.785797/950, current 270.953156/960: elapsed=167377.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 270.936432
last_received_ts = 270.936188
last_seq = 959
current_ts = 271.103821
current_received_ts = 271.103577
current_seq = 969
count = 40
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 270.936432/959, current 271.103821/969: elapsed=167387.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 270.936432/959, current 271.103821/969: elapsed=167387.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 270.953156
last_received_ts = 270.952942
last_seq = 960
current_ts = 271.120544
current_received_ts = 271.120331
current_seq = 970
count = 41
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 270.953156/960, current 271.120544/970: elapsed=167391.0us expected=168292.5us +- 841.5us, error 0.5%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 270.953156/960, current 271.120544/970: elapsed=167391.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 271.103821
last_received_ts = 271.103577
last_seq = 969
current_ts = 271.271118
current_received_ts = 271.270874
current_seq = 979
count = 41
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 271.103821/969, current 271.271118/979: elapsed=167324.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 271.103821/969, current 271.271118/979: elapsed=167324.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 271.120544
last_received_ts = 271.120331
last_seq = 970
current_ts = 271.287872
current_received_ts = 271.287628
current_seq = 980
count = 42
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 271.120544/970, current 271.287872/980: elapsed=167307.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 271.120544/970, current 271.287872/980: elapsed=167307.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 271.271118
last_received_ts = 271.270874
last_seq = 979
current_ts = 271.438416
current_received_ts = 271.438202
current_seq = 989
count = 42
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 271.271118/979, current 271.438416/989: elapsed=167292.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 271.271118/979, current 271.438416/989: elapsed=167292.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 271.287872
last_received_ts = 271.287628
last_seq = 980
current_ts = 271.455170
current_received_ts = 271.454742
current_seq = 990
count = 43
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 271.287872/980, current 271.455170/990: elapsed=167304.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 271.287872/980, current 271.455170/990: elapsed=167304.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 271.438416
last_received_ts = 271.438202
last_seq = 989
current_ts = 271.605743
current_received_ts = 271.605469
current_seq = 999
count = 43
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 271.438416/989, current 271.605743/999: elapsed=167315.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 271.438416/989, current 271.605743/999: elapsed=167315.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = flip
last_ts = 271.455170
last_received_ts = 271.454742
last_seq = 990
current_ts = 271.622467
current_received_ts = 271.622253
current_seq = 1000
count = 44
seq_step = 1
(kms_flip:2258) DEBUG: flip ts/seq: last 271.455170/990, current 271.622467/1000: elapsed=167303.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent flip ts/seq: last 271.455170/990, current 271.622467/1000: elapsed=167303.0us expected=168292.5us
(kms_flip:2258) DEBUG: name = vblank
last_ts = 271.605743
last_received_ts = 271.605469
last_seq = 999
current_ts = 271.773041
current_received_ts = 271.772797
current_seq = 1009
count = 44
seq_step = 10
(kms_flip:2258) DEBUG: vblank ts/seq: last 271.605743/999, current 271.773041/1009: elapsed=167297.0us expected=168292.5us +- 841.5us, error 0.6%
(kms_flip:2258) DEBUG: inconsistent vblank ts/seq: last 271.605743/999, current 271.773041/1009: elapsed=167297.0us expected=168292.5us
(kms_flip:2258) INFO: Event flip: expected 448, counted 450, passrate = 80.00%, encoder type 2
(kms_flip:2258) DEBUG: dropped frames, expected 448, counted 450, passrate = 80.00%, encoder type 2
(kms_flip:2258) INFO: Event vblank: expected 448, counted 450, passrate = 77.78%, encoder type 2
(kms_flip:2258) DEBUG: dropped frames, expected 448, counted 450, passrate = 77.78%, encoder type 2
(kms_flip:2258) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2258) CRITICAL: Failed assertion: !retried
(kms_flip:2258) igt_core-INFO: Stack trace:
(kms_flip:2258) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2258) igt_core-INFO:   #1 ../tests/kms_flip.c:1071 run_test_on_crtc_set()
(kms_flip:2258) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2258) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
(kms_flip:2258) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2258) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2258) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2258) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A3: FAIL (19.094s)
Dmesg
<6> [267.269363] [IGT] kms_flip: starting dynamic subtest C-HDMI-A3
<7> [267.269747] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:561]
<7> [267.269897] i915 0000:03:00.0: [drm:drm_mode_addfb2] [FB:587]
<7> [267.270302] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.270760] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.291565] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.291928] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.297791] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.298211] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.318439] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.318786] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [267.344283] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]
<7> [267.344431] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C]
<7> [267.344511] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.enable (expected yes, found no)
<7> [267.344738] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.active (expected yes, found no)
<7> [267.344938] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1)
<7> [267.345181] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in lane_count (expected 4, found 0)
<7> [267.345419] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)
<7> [267.345660] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [267.345880] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)
<7> [267.346104] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)
<7> [267.346359] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)
<7> [267.346585] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)
<7> [267.346811] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)
<7> [267.347008] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)
<7> [267.347258] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)
<7> [267.347514] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)
<7> [267.347711] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)
<7> [267.347937] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)
<7> [267.348273] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)
<7> [267.348500] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)
<7> [267.348710] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)
<7> [267.348937] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)
<7> [267.349194] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)
<7> [267.349420] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)
<7> [267.349646] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)
<7> [267.349886] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)
<7> [267.350123] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)
<7> [267.350365] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)
<7> [267.350579] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)
<7> [267.350804] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)
<7> [267.351019] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)
<7> [267.351268] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)
<7> [267.351494] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [267.351721] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)
<7> [267.351933] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)
<7> [267.352173] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [267.352375] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)
<7> [267.352576] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)
<7> [267.352778] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe C] fastset requirement not met in port_clock (expected 148500, found 0)
<7> [267.352981] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe C] fastset requirement not met, forcing full modeset
<7> [267.353243] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xd -> 0x1 (total dbuf slices 0xf), mbus joined? no->no
<7> [267.353435] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:269:pipe C] dbuf slices 0xc -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x4 -> 0x0
<7> [267.353651] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor C] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0
<7> [267.353860] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe C] min cdclk: 74250 kHz -> 0 kHz
<7> [267.354069] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz
<7> [267.354304] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [267.354505] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:269:pipe C] enable: no [modeset]
<7> [267.354707] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:153:plane 1C] fb: [NOFB], visible: no
<7> [267.354908] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:183:plane 2C] fb: [NOFB], visible: no
<7> [267.355146] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:213:plane 3C] fb: [NOFB], visible: no
<7> [267.355347] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:243:plane 4C] fb: [NOFB], visible: no
<7> [267.355546] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:253:plane 5C] fb: [NOFB], visible: no
<7> [267.355747] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:cursor C] fb: [NOFB], visible: no
<7> [267.356441] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe C
<7> [267.369265] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D
<7> [267.369537] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [267.369735] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST A]
<7> [267.369932] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST B]
<7> [267.370137] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST C]
<7> [267.370333] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:512:DP-MST D]
<7> [267.370528] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DDI B/PHY B]
<7> [267.370722] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST A]
<7> [267.370917] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST B]
<7> [267.371155] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST C]
<7> [267.371351] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:525:DP-MST D]
<7> [267.371547] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DDI C/PHY C]
<7> [267.371742] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST A]
<7> [267.371938] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST B]
<7> [267.372176] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST C]
<7> [267.372372] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:540:DP-MST D]
<7> [267.372567] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI D/PHY D]
<7> [267.372782] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [267.372978] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [267.373211] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [267.373407] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [267.373602] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:556:HDMI-A-3]
<7> [267.373836] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [267.374208] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_C
<7> [267.374471] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2
<7> [267.374716] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe C]
<7> [267.375116] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]
<7> [267.375279] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]
<7> [267.375429] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]
<7> [267.375458] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:556:HDMI-A-3]
<7> [267.375530] i915 0000:03:00.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:556:HDMI-A-3] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36)
<7> [267.375744] i915 0000:03:00.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)
<7> [267.375929] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [267.376209] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:547:DDI D/PHY D] [CRTC:387:pipe B]
<7> [267.376397] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [267.376600] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [267.376802] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [267.377004] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in lane_count (expected 0, found 4)
<7> [267.377273] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)
<7> [267.377476] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [267.377678] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)
<7> [267.377880] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)
<7> [267.378119] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)
<7> [267.378320] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)
<7> [267.378523] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)
<7> [267.378725] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)
<7> [267.378926] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)
<7> [267.379165] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)
<7> [267.379367] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)
<7> [267.379568] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)
<7> [267.379769] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)
<7> [267.379970] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)
<7> [267.380212] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)
<7> [267.380414] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)
<7> [267.380615] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)
<7> [267.380817] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)
<7> [267.381018] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)
<7> [267.381257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)
<7> [267.381458] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)
<7> [267.381659] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)
<7> [267.381859] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)
<7> [267.382065] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)
<7> [267.382329] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)
<7> [267.382531] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)
<7> [267.382731] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [267.382933] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)
<7> [267.383171] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)
<7> [267.383373] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [267.383575] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)
<7> [267.383776] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)
<7> [267.383977] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in port_clock (expected 0, found 148500)
<7> [267.384261] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe B] fastset requirement not met, forcing full modeset
<7> [267.384486] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no
<7> [267.384679] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2
<7> [267.384895] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963
<7> [267.385126] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85
<7> [267.385318] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm
<7> [267.385508] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0
<7> [267.385699] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0
<7> [267.385890] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0
<7> [267.386134] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe B] data rate 594000 num active planes 1
<7> [267.386335] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624
<7> [267.386535] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1
<7> [267.386749] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe B] min cdclk: 0 kHz -> 74250 kHz
<7> [267.386969] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz
<7> [267.387204] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [267.387407] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe B] enable: yes [modeset]
<7> [267.387608] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB
<7> [267.387809] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [267.388010] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [267.388252] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [267.388453] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [267.388653] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [267.388852] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [267.389052] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2
<7> [267.389290] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [267.389491] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36
<7> [267.389692] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125
<7> [267.389893] i915 0000:03:00.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> [267.390132] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [267.390334] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [267.390536] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [267.390738] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5
<7> [267.390939] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [267.391177] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pixel rate 148500, min cdclk 74250, min voltage level 0
<7> [267.391377] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0
<7> [267.391577] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0
<7> [267.391777] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0
<7> [267.391977] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [267.392217] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [267.392418] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [267.392619] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440
<7> [267.392819] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [267.393020] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [267.393260] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [267.393317] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [267.393461] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.393563] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5
<7> [267.393662] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.393773] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01
<7> [267.393861] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.394180] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [267.394394] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [267.394594] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.394794] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.394995] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [267.395233] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [267.395434] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1B] fb: [FB:561] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes
<7> [267.395637] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [267.395838] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0
<7> [267.396039] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2B] fb: [NOFB], visible: no
<7> [267.396281] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3B] fb: [NOFB], visible: no
<7> [267.396482] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4B] fb: [NOFB], visible: no
<7> [267.396682] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5B] fb: [NOFB], visible: no
<7> [267.396883] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor B] fb: [NOFB], visible: no
<7> [267.397535] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [267.397863] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00
<7> [267.398319] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [267.398543] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B
<7> [267.398796] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [267.398992] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST A]
<7> [267.399227] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST B]
<7> [267.399422] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST C]
<7> [267.399618] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:512:DP-MST D]
<7> [267.399813] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DDI B/PHY B]
<7> [267.400007] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST A]
<7> [267.400243] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST B]
<7> [267.400438] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST C]
<7> [267.400632] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:525:DP-MST D]
<7> [267.400827] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DDI C/PHY C]
<7> [267.401022] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST A]
<7> [267.401223] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST B]
<7> [267.401418] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST C]
<7> [267.401614] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:540:DP-MST D]
<7> [267.401809] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI D/PHY D]
<7> [267.402004] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [267.402234] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [267.402429] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [267.402625] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [267.402820] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3
<7> [267.403266] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D
<7> [267.403598] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [267.422692] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:556:HDMI-A-3]
<7> [267.423035] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe B]
<7> [278.210981] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]
<7> [278.211897] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe C]
<7> [278.212686] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]
<7> [278.213062] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.enable (expected yes, found no)
<7> [278.214149] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.active (expected yes, found no)
<7> [278.215184] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)
<7> [278.216110] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in lane_count (expected 4, found 0)
<7> [278.216367] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000040, found 0x00000000)
<7> [278.216566] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [278.216763] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1920, found 0)
<7> [278.216960] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 2200, found 0)
<7> [278.217241] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1920, found 0)
<7> [278.217453] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 2200, found 0)
<7> [278.217710] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2008, found 0)
<7> [278.217907] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2052, found 0)
<7> [278.218162] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1080, found 0)
<7> [278.218389] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1080, found 0)
<7> [278.218615] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1084, found 0)
<7> [278.218841] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1089, found 0)
<7> [278.219062] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1125, found 0)
<7> [278.219316] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1125, found 0)
<7> [278.219542] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1920, found 0)
<7> [278.219766] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 2200, found 0)
<7> [278.219963] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1920, found 0)
<7> [278.220213] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 2200, found 0)
<7> [278.220499] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2008, found 0)
<7> [278.220712] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2052, found 0)
<7> [278.220935] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1080, found 0)
<7> [278.221152] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1080, found 0)
<7> [278.221363] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1084, found 0)
<7> [278.221574] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1089, found 0)
<7> [278.221785] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1125, found 0)
<7> [278.222001] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1125, found 0)
<7> [278.222212] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [278.222422] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 1, found 0)
<7> [278.222634] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 4, found 0)
<7> [278.222845] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [278.223062] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 148500, found 0)
<7> [278.223273] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 148500, found 0)
<7> [278.223484] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in port_clock (expected 148500, found 0)
<7> [278.223695] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe B] fastset requirement not met, forcing full modeset
<7> [278.223924] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x3 -> 0x1 (total dbuf slices 0xf), mbus joined? no->no
<7> [278.224134] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe B] dbuf slices 0x3 -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x2 -> 0x0
<7> [278.224362] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1B] ddb ( 0 - 1963) -> ( 0 - 0), size 1963 -> 0
<7> [278.224562] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor B] ddb (1963 - 2048) -> ( 0 - 0), size 85 -> 0
<7> [278.224763] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [278.224968] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] lines 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [278.225170] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] blocks 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [278.225369] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] min_ddb 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [278.225586] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe B] data rate 0 num active planes 0
<7> [278.225797] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 0
<7> [278.226059] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1
<7> [278.226353] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe B] min cdclk: 74250 kHz -> 0 kHz
<7> [278.226565] i915 0000:03:00.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 9282 kHz -> 0 kHz
<7> [278.226762] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz
<7> [278.227016] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [278.227286] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe B] enable: no [modeset]
<7> [278.227483] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1B] fb: [NOFB], visible: no
<7> [278.227680] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2B] fb: [NOFB], visible: no
<7> [278.227876] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3B] fb: [NOFB], visible: no
<7> [278.228154] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4B] fb: [NOFB], visible: no
<7> [278.228398] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5B] fb: [NOFB], visible: no
<7> [278.228593] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor B] fb: [NOFB], visible: no
<7> [278.228907] i915 0000:03:00.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [278.240070] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DDI_IO_D
<7> [278.240336] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [278.240530] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST A]
<7> [278.240722] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST B]
<7> [278.240961] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST C]
<7> [278.241190] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:512:DP-MST D]
<7> [278.241410] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DDI B/PHY B]
<7> [278.241600] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST A]
<7> [278.241814] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST B]
<7> [278.242100] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST C]
<7> [278.242292] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:525:DP-MST D]
<7> [278.242512] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DDI C/PHY C]
<7> [278.242704] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST A]
<7> [278.242933] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST B]
<7> [278.243163] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST C]
<7> [278.243353] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:540:DP-MST D]
<7> [278.243587] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI D/PHY D]
<7> [278.243838] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [278.244072] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [278.244292] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [278.244483] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [278.244692] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:556:HDMI-A-3]
<7> [278.245021] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [278.245370] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_B
<7> [278.245628] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling PW_2
<7> [278.245960] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe B]
<7> [278.246412] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]
<7> [278.246588] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe B]
<7> [278.246617] i915 0000:03:00.0: [drm:drm_mode_setcrtc] [CONNECTOR:556:HDMI-A-3]
<7> [278.246690] i915 0000:03:00.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:556:HDMI-A-3] Limiting target display pipe bpp to 24 (EDID bpp 0, max requested bpp 36, max platform bpp 36)
<7> [278.246951] i915 0000:03:00.0: [drm:intel_hdmi_compute_output_format [i915]] picking 8 bpc for HDMI output (pipe bpp: 24)
<7> [278.247190] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [278.247389] i915 0000:03:00.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:547:DDI D/PHY D] [CRTC:387:pipe B]
<7> [278.247590] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [278.247869] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [278.248110] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [278.248337] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in lane_count (expected 0, found 4)
<7> [278.248551] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)
<7> [278.248790] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [278.249031] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)
<7> [278.249257] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)
<7> [278.249470] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)
<7> [278.249670] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)
<7> [278.249939] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)
<7> [278.250177] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)
<7> [278.250403] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)
<7> [278.250616] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)
<7> [278.250870] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1084)
<7> [278.251094] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1089)
<7> [278.251296] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)
<7> [278.251497] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)
<7> [278.251704] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)
<7> [278.251939] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)
<7> [278.252140] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)
<7> [278.252342] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)
<7> [278.252544] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)
<7> [278.252789] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)
<7> [278.252991] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)
<7> [278.253193] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)
<7> [278.253394] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1084)
<7> [278.253595] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1089)
<7> [278.253803] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)
<7> [278.254004] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)
<7> [278.254206] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [278.254407] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)
<7> [278.254609] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.flags (4) (expected 0, found 4)
<7> [278.254848] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [278.255050] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148500)
<7> [278.255250] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148500)
<7> [278.255452] i915 0000:03:00.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe B] fastset requirement not met in port_clock (expected 0, found 148500)
<7> [278.255660] i915 0000:03:00.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe B] fastset requirement not met, forcing full modeset
<7> [278.255917] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0x3 (total dbuf slices 0xf), mbus joined? no->no
<7> [278.256111] i915 0000:03:00.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe B] dbuf slices 0x0 -> 0x3, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x2
<7> [278.256327] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1B] ddb ( 0 - 0) -> ( 0 - 1963), size 0 -> 1963
<7> [278.256519] i915 0000:03:00.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor B] ddb ( 0 - 0) -> (1963 - 2048), size 0 -> 85
<7> [278.256815] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5,*wm6,*wm7,*twm, swm, stwm
<7> [278.257008] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 4, 4, 5, 9, 11, 17, 25, 0, 0, 0
<7> [278.257199] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 62, 62, 62, 78, 139, 169, 261, 383, 137, 0, 0
<7> [278.257389] i915 0000:03:00.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 123, 123, 123, 184, 245, 245, 367, 489, 138, 0, 0
<7> [278.257594] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe B] data rate 594000 num active planes 1
<7> [278.257833] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 50000 required 624
<7> [278.258034] i915 0000:03:00.0: [drm:intel_bw_atomic_check [i915]] No SAGV, using single QGV point mask 0x1
<7> [278.258248] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe B] min cdclk: 0 kHz -> 74250 kHz
<7> [278.258464] i915 0000:03:00.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 0 kHz -> 9282 kHz
<7> [278.258706] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 163200 kHz, actual 163200 kHz
<7> [278.258906] i915 0000:03:00.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [278.259107] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe B] enable: yes [modeset]
<7> [278.259308] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB
<7> [278.259509] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [278.259747] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [278.259948] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [278.260148] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [278.260349] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [278.260550] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [278.260817] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 2
<7> [278.261017] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0
<7> [278.261218] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1125, vmax: 1125, flipline: 1125, pipeline full: 0, guardband: 45 vsync start: 41, vsync end: 36
<7> [278.261419] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1080, vmax vblank: 1080, vmin vtotal: 1125, vmax vtotal: 1125
<7> [278.261660] i915 0000:03:00.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> [278.261861] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [278.262063] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5
<7> [278.262265] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [278.262467] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x40 0x5
<7> [278.262705] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148500, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1084-1089 vt=1125, flags=0x5
<7> [278.262906] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] port clock: 148500, pixel rate 148500, min cdclk 74250, min voltage level 0
<7> [278.263107] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] linetime: 119, ips linetime: 0
<7> [278.263308] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0
<7> [278.263508] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0
<7> [278.263749] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [278.263807] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [278.263950] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [278.264053] i915 0000:03:00.0: [drm:gen9_enable_dc5 [i915]] Enabling DC5
<7> [278.264150] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [278.264259] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 01
<7> [278.264350] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x24414, dpll_md: 0x18000000, fp0: 0x8801ef8, fp1: 0x2b000440
<7> [278.264551] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [278.264739] i915 0000:03:00.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [278.264933] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [278.265172] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [278.265372] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.265613] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.265813] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.266057] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [278.266253] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [278.266467] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.266714] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.266940] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [278.267166] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [278.267375] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1B] fb: [FB:561] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes
<7> [278.267626] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [278.267853] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0
<7> [278.268080] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2B] fb: [NOFB], visible: no
<7> [278.268289] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3B] fb: [NOFB], visible: no
<7> [278.268489] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4B] fb: [NOFB], visible: no
<7> [278.268738] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5B] fb: [NOFB], visible: no
<7> [278.268990] i915 0000:03:00.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor B] fb: [NOFB], visible: no
<7> [278.269270] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [278.269473] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [278.269864] i915 0000:03:00.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 01 to 00
<7> [278.270276] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [278.270505] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling PW_B
<7> [278.270858] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [278.271081] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:509:DP-MST A]
<7> [278.271300] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:510:DP-MST B]
<7> [278.271496] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:511:DP-MST C]
<7> [278.271809] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:512:DP-MST D]
<7> [278.272000] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DDI B/PHY B]
<7> [278.272207] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:522:DP-MST A]
<7> [278.272402] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:523:DP-MST B]
<7> [278.272649] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:524:DP-MST C]
<7> [278.272870] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:525:DP-MST D]
<7> [278.273089] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:535:DDI C/PHY C]
<7> [278.273295] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST A]
<7> [278.273515] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST B]
<7> [278.273763] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST C]
<7> [278.273984] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:540:DP-MST D]
<7> [278.274201] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI D/PHY D]
<7> [278.274392] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [278.274637] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [278.274857] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [278.275062] i915 0000:03:00.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [278.275267] i915 0000:03:00.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x3
<7> [278.275755] i915 0000:03:00.0: [drm:intel_power_well_enable [i915]] enabling DDI_IO_D
<7> [278.276106] i915 0000:03:00.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [278.295335] i915 0000:03:00.0: [drm:verify_connector_state [i915]] [CONNECTOR:556:HDMI-A-3]
<7> [278.295684] i915 0000:03:00.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe B]
<6> [286.363450] [IGT] kms_flip: finished subtest C-HDMI-A3, FAIL
Created at 2026-04-21 19:47:20