Results for igt@kms_flip@wf_vblank-ts-check-interruptible@c-edp1

Result: Fail

integration-manifest git-log-oneline i915_display_info10 igt_runner10 runtimes10 results10.json results10-i915-load.json guc_logs10.tar i915_display_info_post_exec10 boot10 dmesg10

DetailValue
Duration 21.00 seconds
Hostname 
shard-mtlp-7
Igt-Version 
IGT-Version: 2.4-ga5c5d6558 (x86_64) (Linux: 7.0.0-CI_DRM_18366-gd431883e767c+ x86_64)
Out 
Starting dynamic subtest: C-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11104.7us +- 2.358us accuracy 0.06%
vblank interval differs from modeline! expected 11111.1us, measured 11105us +- 2.358us, difference 6.4us (2.7 sigma)
Event vblank: expected 676, counted 680, passrate = 82.35%, encoder type 2
Expected frametime: 11111us; measured 10932.2us +- 2.401us accuracy 0.07%
vblank interval differs from modeline! expected 11111.1us, measured 10932us +- 2.401us, difference 178.9us (74.5 sigma)
Event vblank: expected 694, counted 690, passrate = 33.33%, 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:2220 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (20.998s)
Err 
Starting dynamic subtest: C-eDP1
(kms_flip:2605) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2605) CRITICAL: Failed assertion: !retried
(kms_flip:2605) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.247513
last_received_ts = 255.247192
last_seq = 540
current_ts = 255.358566
current_received_ts = 255.358246
current_seq = 550
count = 49
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.247513/540, current 255.358566/550: elapsed=111054.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.358566
last_received_ts = 255.358246
last_seq = 550
current_ts = 255.469620
current_received_ts = 255.469299
current_seq = 560
count = 50
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.358566/550, current 255.469620/560: elapsed=111053.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.469620
last_received_ts = 255.469299
last_seq = 560
current_ts = 255.580673
current_received_ts = 255.580353
current_seq = 570
count = 51
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.469620/560, current 255.580673/570: elapsed=111052.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.580673
last_received_ts = 255.580353
last_seq = 570
current_ts = 255.691727
current_received_ts = 255.691406
current_seq = 580
count = 52
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.580673/570, current 255.691727/580: elapsed=111055.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.691727
last_received_ts = 255.691406
last_seq = 580
current_ts = 255.802780
current_received_ts = 255.802444
current_seq = 590
count = 53
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.691727/580, current 255.802780/590: elapsed=111053.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.802780
last_received_ts = 255.802444
last_seq = 590
current_ts = 255.913834
current_received_ts = 255.913498
current_seq = 600
count = 54
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.802780/590, current 255.913834/600: elapsed=111053.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 255.913834
last_received_ts = 255.913498
last_seq = 600
current_ts = 256.024902
current_received_ts = 256.024597
current_seq = 610
count = 55
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 255.913834/600, current 256.024902/610: elapsed=111053.0us expected=111046.9us +- 555.2us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.024902
last_received_ts = 256.024597
last_seq = 610
current_ts = 256.132660
current_received_ts = 256.132324
current_seq = 620
count = 56
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.024902/610, current 256.132660/620: elapsed=107755.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.024902/610, current 256.132660/620: elapsed=107755.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.132660
last_received_ts = 256.132324
last_seq = 620
current_ts = 256.240326
current_received_ts = 256.240021
current_seq = 630
count = 57
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.132660/620, current 256.240326/630: elapsed=107673.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.132660/620, current 256.240326/630: elapsed=107673.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.240326
last_received_ts = 256.240021
last_seq = 630
current_ts = 256.347992
current_received_ts = 256.347687
current_seq = 640
count = 58
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.240326/630, current 256.347992/640: elapsed=107681.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.240326/630, current 256.347992/640: elapsed=107681.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.347992
last_received_ts = 256.347687
last_seq = 640
current_ts = 256.455688
current_received_ts = 256.455353
current_seq = 650
count = 59
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.347992/640, current 256.455688/650: elapsed=107677.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.347992/640, current 256.455688/650: elapsed=107677.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.455688
last_received_ts = 256.455353
last_seq = 650
current_ts = 256.563354
current_received_ts = 256.563019
current_seq = 660
count = 60
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.455688/650, current 256.563354/660: elapsed=107681.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.455688/650, current 256.563354/660: elapsed=107681.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.563354
last_received_ts = 256.563019
last_seq = 660
current_ts = 256.671021
current_received_ts = 256.670715
current_seq = 670
count = 61
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.563354/660, current 256.671021/670: elapsed=107676.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.563354/660, current 256.671021/670: elapsed=107676.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.671021
last_received_ts = 256.670715
last_seq = 670
current_ts = 256.778717
current_received_ts = 256.778412
current_seq = 680
count = 62
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.671021/670, current 256.778717/680: elapsed=107682.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.671021/670, current 256.778717/680: elapsed=107682.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.778717
last_received_ts = 256.778412
last_seq = 680
current_ts = 256.886383
current_received_ts = 256.886078
current_seq = 690
count = 63
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.778717/680, current 256.886383/690: elapsed=107680.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.778717/680, current 256.886383/690: elapsed=107680.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.886383
last_received_ts = 256.886078
last_seq = 690
current_ts = 256.994080
current_received_ts = 256.993744
current_seq = 700
count = 64
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.886383/690, current 256.994080/700: elapsed=107679.0us expected=111046.9us +- 555.2us, error 3.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.886383/690, current 256.994080/700: elapsed=107679.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 256.994080
last_received_ts = 256.993744
last_seq = 700
current_ts = 257.102051
current_received_ts = 257.101715
current_seq = 710
count = 65
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 256.994080/700, current 257.102051/710: elapsed=107970.0us expected=111046.9us +- 555.2us, error 2.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 256.994080/700, current 257.102051/710: elapsed=107970.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 257.102051
last_received_ts = 257.101715
last_seq = 710
current_ts = 257.210144
current_received_ts = 257.209839
current_seq = 720
count = 66
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 257.102051/710, current 257.210144/720: elapsed=108097.0us expected=111046.9us +- 555.2us, error 2.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 257.102051/710, current 257.210144/720: elapsed=108097.0us expected=111046.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 257.210144
last_received_ts = 257.209839
last_seq = 720
current_ts = 257.318237
current_received_ts = 257.317902
current_seq = 730
count = 67
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 257.210144/720, current 257.318237/730: elapsed=108102.0us expected=111046.9us +- 555.2us, error 2.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 257.210144/720, current 257.318237/730: elapsed=108102.0us expected=111046.9us
(kms_flip:2605) INFO: Event vblank: expected 676, counted 680, passrate = 82.35%, encoder type 2
(kms_flip:2605) DEBUG: dropped frames, expected 676, counted 680, passrate = 82.35%, encoder type 2
(kms_flip:2605) DEBUG: Retrying without a hotplug event
(kms_flip:2605) DEBUG: No stale events found
(kms_flip:2605) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2605) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2605) INFO: Expected frametime: 11111us; measured 10932.2us +- 2.401us accuracy 0.07%
(kms_flip:2605) INFO: vblank interval differs from modeline! expected 11111.1us, measured 10932us +- 2.401us, difference 178.9us (74.5 sigma)
(kms_flip:2605) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 261.676636
current_received_ts = 261.676331
current_seq = 761
count = 0
seq_step = 10
(kms_flip:2605) DEBUG: name = vblank
last_ts = 261.676636
last_received_ts = 261.676331
last_seq = 761
current_ts = 261.785950
current_received_ts = 261.785614
current_seq = 771
count = 1
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 261.676636/761, current 261.785950/771: elapsed=109325.0us expected=109321.9us +- 546.6us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 261.785950
last_received_ts = 261.785614
last_seq = 771
current_ts = 261.895264
current_received_ts = 261.894958
current_seq = 781
count = 2
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 261.785950/771, current 261.895264/781: elapsed=109321.0us expected=109321.9us +- 546.6us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 261.895264
last_received_ts = 261.894958
last_seq = 781
current_ts = 262.004608
current_received_ts = 262.004272
current_seq = 791
count = 3
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 261.895264/781, current 262.004608/791: elapsed=109325.0us expected=109321.9us +- 546.6us, error 0.0%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.004608
last_received_ts = 262.004272
last_seq = 791
current_ts = 262.114075
current_received_ts = 262.113800
current_seq = 801
count = 4
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.004608/791, current 262.114075/801: elapsed=109494.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.114075
last_received_ts = 262.113800
last_seq = 801
current_ts = 262.223633
current_received_ts = 262.223297
current_seq = 811
count = 5
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.114075/801, current 262.223633/811: elapsed=109542.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.223633
last_received_ts = 262.223297
last_seq = 811
current_ts = 262.333160
current_received_ts = 262.332855
current_seq = 821
count = 6
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.223633/811, current 262.333160/821: elapsed=109542.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.333160
last_received_ts = 262.332855
last_seq = 821
current_ts = 262.442719
current_received_ts = 262.442383
current_seq = 831
count = 7
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.333160/821, current 262.442719/831: elapsed=109537.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.442719
last_received_ts = 262.442383
last_seq = 831
current_ts = 262.552246
current_received_ts = 262.551910
current_seq = 841
count = 8
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.442719/831, current 262.552246/841: elapsed=109541.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.552246
last_received_ts = 262.551910
last_seq = 841
current_ts = 262.661804
current_received_ts = 262.661469
current_seq = 851
count = 9
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.552246/841, current 262.661804/851: elapsed=109540.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.661804
last_received_ts = 262.661469
last_seq = 851
current_ts = 262.771332
current_received_ts = 262.770935
current_seq = 861
count = 10
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.661804/851, current 262.771332/861: elapsed=109539.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.771332
last_received_ts = 262.770935
last_seq = 861
current_ts = 262.880859
current_received_ts = 262.880554
current_seq = 871
count = 11
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.771332/861, current 262.880859/871: elapsed=109542.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.880859
last_received_ts = 262.880554
last_seq = 871
current_ts = 262.990417
current_received_ts = 262.990082
current_seq = 881
count = 12
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.880859/871, current 262.990417/881: elapsed=109539.0us expected=109321.9us +- 546.6us, error 0.2%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 262.990417
last_received_ts = 262.990082
last_seq = 881
current_ts = 263.100067
current_received_ts = 263.099731
current_seq = 891
count = 13
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 262.990417/881, current 263.100067/891: elapsed=109666.0us expected=109321.9us +- 546.6us, error 0.3%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.100067
last_received_ts = 263.099731
last_seq = 891
current_ts = 263.209808
current_received_ts = 263.209503
current_seq = 901
count = 14
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.100067/891, current 263.209808/901: elapsed=109729.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.209808
last_received_ts = 263.209503
last_seq = 901
current_ts = 263.319550
current_received_ts = 263.319214
current_seq = 911
count = 15
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.209808/901, current 263.319550/911: elapsed=109731.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.319550
last_received_ts = 263.319214
last_seq = 911
current_ts = 263.429260
current_received_ts = 263.428925
current_seq = 921
count = 16
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.319550/911, current 263.429260/921: elapsed=109729.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.429260
last_received_ts = 263.428925
last_seq = 921
current_ts = 263.539001
current_received_ts = 263.538666
current_seq = 931
count = 17
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.429260/921, current 263.539001/931: elapsed=109731.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.539001
last_received_ts = 263.538666
last_seq = 931
current_ts = 263.648712
current_received_ts = 263.648407
current_seq = 941
count = 18
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.539001/931, current 263.648712/941: elapsed=109726.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.648712
last_received_ts = 263.648407
last_seq = 941
current_ts = 263.758453
current_received_ts = 263.758148
current_seq = 951
count = 19
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.648712/941, current 263.758453/951: elapsed=109729.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.758453
last_received_ts = 263.758148
last_seq = 951
current_ts = 263.868195
current_received_ts = 263.867859
current_seq = 961
count = 20
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.758453/951, current 263.868195/961: elapsed=109730.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.868195
last_received_ts = 263.867859
last_seq = 961
current_ts = 263.977905
current_received_ts = 263.977631
current_seq = 971
count = 21
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.868195/961, current 263.977905/971: elapsed=109729.0us expected=109321.9us +- 546.6us, error 0.4%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 263.977905
last_received_ts = 263.977631
last_seq = 971
current_ts = 264.087738
current_received_ts = 264.087463
current_seq = 981
count = 22
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 263.977905/971, current 264.087738/981: elapsed=109824.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.087738
last_received_ts = 264.087463
last_seq = 981
current_ts = 264.197632
current_received_ts = 264.197296
current_seq = 991
count = 23
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.087738/981, current 264.197632/991: elapsed=109892.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.087738/981, current 264.197632/991: elapsed=109892.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.197632
last_received_ts = 264.197296
last_seq = 991
current_ts = 264.307526
current_received_ts = 264.307190
current_seq = 1001
count = 24
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.197632/991, current 264.307526/1001: elapsed=109896.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.197632/991, current 264.307526/1001: elapsed=109896.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.307526
last_received_ts = 264.307190
last_seq = 1001
current_ts = 264.417419
current_received_ts = 264.417114
current_seq = 1011
count = 25
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.307526/1001, current 264.417419/1011: elapsed=109894.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.307526/1001, current 264.417419/1011: elapsed=109894.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.417419
last_received_ts = 264.417114
last_seq = 1011
current_ts = 264.527313
current_received_ts = 264.526978
current_seq = 1021
count = 26
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.417419/1011, current 264.527313/1021: elapsed=109899.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.417419/1011, current 264.527313/1021: elapsed=109899.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.527313
last_received_ts = 264.526978
last_seq = 1021
current_ts = 264.637207
current_received_ts = 264.636871
current_seq = 1031
count = 27
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.527313/1021, current 264.637207/1031: elapsed=109896.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.527313/1021, current 264.637207/1031: elapsed=109896.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.637207
last_received_ts = 264.636871
last_seq = 1031
current_ts = 264.747101
current_received_ts = 264.746765
current_seq = 1041
count = 28
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.637207/1031, current 264.747101/1041: elapsed=109894.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.637207/1031, current 264.747101/1041: elapsed=109894.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.747101
last_received_ts = 264.746765
last_seq = 1041
current_ts = 264.856995
current_received_ts = 264.856659
current_seq = 1051
count = 29
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.747101/1041, current 264.856995/1051: elapsed=109897.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.747101/1041, current 264.856995/1051: elapsed=109897.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.856995
last_received_ts = 264.856659
last_seq = 1051
current_ts = 264.966888
current_received_ts = 264.966583
current_seq = 1061
count = 30
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.856995/1051, current 264.966888/1061: elapsed=109895.0us expected=109321.9us +- 546.6us, error 0.5%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.856995/1051, current 264.966888/1061: elapsed=109895.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 264.966888
last_received_ts = 264.966583
last_seq = 1061
current_ts = 265.076843
current_received_ts = 265.076538
current_seq = 1071
count = 31
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 264.966888/1061, current 265.076843/1071: elapsed=109958.0us expected=109321.9us +- 546.6us, error 0.6%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 264.966888/1061, current 265.076843/1071: elapsed=109958.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.076843
last_received_ts = 265.076538
last_seq = 1071
current_ts = 265.186890
current_received_ts = 265.186615
current_seq = 1081
count = 32
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.076843/1071, current 265.186890/1081: elapsed=110045.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.076843/1071, current 265.186890/1081: elapsed=110045.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.186890
last_received_ts = 265.186615
last_seq = 1081
current_ts = 265.296936
current_received_ts = 265.296631
current_seq = 1091
count = 33
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.186890/1081, current 265.296936/1091: elapsed=110039.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.186890/1081, current 265.296936/1091: elapsed=110039.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.296936
last_received_ts = 265.296631
last_seq = 1091
current_ts = 265.406982
current_received_ts = 265.406647
current_seq = 1101
count = 34
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.296936/1091, current 265.406982/1101: elapsed=110041.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.296936/1091, current 265.406982/1101: elapsed=110041.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.406982
last_received_ts = 265.406647
last_seq = 1101
current_ts = 265.517029
current_received_ts = 265.516754
current_seq = 1111
count = 35
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.406982/1101, current 265.517029/1111: elapsed=110039.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.406982/1101, current 265.517029/1111: elapsed=110039.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.517029
last_received_ts = 265.516754
last_seq = 1111
current_ts = 265.627075
current_received_ts = 265.626740
current_seq = 1121
count = 36
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.517029/1111, current 265.627075/1121: elapsed=110041.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.517029/1111, current 265.627075/1121: elapsed=110041.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.627075
last_received_ts = 265.626740
last_seq = 1121
current_ts = 265.737091
current_received_ts = 265.736786
current_seq = 1131
count = 37
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.627075/1121, current 265.737091/1131: elapsed=110042.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.627075/1121, current 265.737091/1131: elapsed=110042.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.737091
last_received_ts = 265.736786
last_seq = 1131
current_ts = 265.847137
current_received_ts = 265.846832
current_seq = 1141
count = 38
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.737091/1131, current 265.847137/1141: elapsed=110040.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.737091/1131, current 265.847137/1141: elapsed=110040.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.847137
last_received_ts = 265.846832
last_seq = 1141
current_ts = 265.957184
current_received_ts = 265.956879
current_seq = 1151
count = 39
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.847137/1141, current 265.957184/1151: elapsed=110039.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.847137/1141, current 265.957184/1151: elapsed=110039.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 265.957184
last_received_ts = 265.956879
last_seq = 1151
current_ts = 266.067261
current_received_ts = 266.066956
current_seq = 1161
count = 40
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 265.957184/1151, current 266.067261/1161: elapsed=110087.0us expected=109321.9us +- 546.6us, error 0.7%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 265.957184/1151, current 266.067261/1161: elapsed=110087.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.067261
last_received_ts = 266.066956
last_seq = 1161
current_ts = 266.177429
current_received_ts = 266.177124
current_seq = 1171
count = 41
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.067261/1161, current 266.177429/1171: elapsed=110167.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.067261/1161, current 266.177429/1171: elapsed=110167.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.177429
last_received_ts = 266.177124
last_seq = 1171
current_ts = 266.287598
current_received_ts = 266.287262
current_seq = 1181
count = 42
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.177429/1171, current 266.287598/1181: elapsed=110165.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.177429/1171, current 266.287598/1181: elapsed=110165.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.287598
last_received_ts = 266.287262
last_seq = 1181
current_ts = 266.397766
current_received_ts = 266.397430
current_seq = 1191
count = 43
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.287598/1181, current 266.397766/1191: elapsed=110167.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.287598/1181, current 266.397766/1191: elapsed=110167.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.397766
last_received_ts = 266.397430
last_seq = 1191
current_ts = 266.507935
current_received_ts = 266.507629
current_seq = 1201
count = 44
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.397766/1191, current 266.507935/1201: elapsed=110169.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.397766/1191, current 266.507935/1201: elapsed=110169.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.507935
last_received_ts = 266.507629
last_seq = 1201
current_ts = 266.618103
current_received_ts = 266.617767
current_seq = 1211
count = 45
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.507935/1201, current 266.618103/1211: elapsed=110169.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.507935/1201, current 266.618103/1211: elapsed=110169.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.618103
last_received_ts = 266.617767
last_seq = 1211
current_ts = 266.728271
current_received_ts = 266.727966
current_seq = 1221
count = 46
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.618103/1211, current 266.728271/1221: elapsed=110168.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.618103/1211, current 266.728271/1221: elapsed=110168.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.728271
last_received_ts = 266.727966
last_seq = 1221
current_ts = 266.838440
current_received_ts = 266.838135
current_seq = 1231
count = 47
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.728271/1221, current 266.838440/1231: elapsed=110164.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.728271/1221, current 266.838440/1231: elapsed=110164.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.838440
last_received_ts = 266.838135
last_seq = 1231
current_ts = 266.948608
current_received_ts = 266.948303
current_seq = 1241
count = 48
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.838440/1231, current 266.948608/1241: elapsed=110170.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.838440/1231, current 266.948608/1241: elapsed=110170.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 266.948608
last_received_ts = 266.948303
last_seq = 1241
current_ts = 267.058807
current_received_ts = 267.058502
current_seq = 1251
count = 49
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 266.948608/1241, current 267.058807/1251: elapsed=110197.0us expected=109321.9us +- 546.6us, error 0.8%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 266.948608/1241, current 267.058807/1251: elapsed=110197.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.058807
last_received_ts = 267.058502
last_seq = 1251
current_ts = 267.169067
current_received_ts = 267.168762
current_seq = 1261
count = 50
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.058807/1251, current 267.169067/1261: elapsed=110278.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.058807/1251, current 267.169067/1261: elapsed=110278.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.169067
last_received_ts = 267.168762
last_seq = 1261
current_ts = 267.279358
current_received_ts = 267.279053
current_seq = 1271
count = 51
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.169067/1261, current 267.279358/1271: elapsed=110280.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.169067/1261, current 267.279358/1271: elapsed=110280.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.279358
last_received_ts = 267.279053
last_seq = 1271
current_ts = 267.389648
current_received_ts = 267.389313
current_seq = 1281
count = 52
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.279358/1271, current 267.389648/1281: elapsed=110275.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.279358/1271, current 267.389648/1281: elapsed=110275.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.389648
last_received_ts = 267.389313
last_seq = 1281
current_ts = 267.499908
current_received_ts = 267.499603
current_seq = 1291
count = 53
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.389648/1281, current 267.499908/1291: elapsed=110279.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.389648/1281, current 267.499908/1291: elapsed=110279.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.499908
last_received_ts = 267.499603
last_seq = 1291
current_ts = 267.610199
current_received_ts = 267.609863
current_seq = 1301
count = 54
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.499908/1291, current 267.610199/1301: elapsed=110282.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.499908/1291, current 267.610199/1301: elapsed=110282.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.610199
last_received_ts = 267.609863
last_seq = 1301
current_ts = 267.720490
current_received_ts = 267.720184
current_seq = 1311
count = 55
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.610199/1301, current 267.720490/1311: elapsed=110279.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.610199/1301, current 267.720490/1311: elapsed=110279.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.720490
last_received_ts = 267.720184
last_seq = 1311
current_ts = 267.830750
current_received_ts = 267.830444
current_seq = 1321
count = 56
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.720490/1311, current 267.830750/1321: elapsed=110277.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.720490/1311, current 267.830750/1321: elapsed=110277.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.830750
last_received_ts = 267.830444
last_seq = 1321
current_ts = 267.941040
current_received_ts = 267.940704
current_seq = 1331
count = 57
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.830750/1321, current 267.941040/1331: elapsed=110280.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.830750/1321, current 267.941040/1331: elapsed=110280.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 267.941040
last_received_ts = 267.940704
last_seq = 1331
current_ts = 268.051331
current_received_ts = 268.051025
current_seq = 1341
count = 58
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 267.941040/1331, current 268.051331/1341: elapsed=110296.0us expected=109321.9us +- 546.6us, error 0.9%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 267.941040/1331, current 268.051331/1341: elapsed=110296.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.051331
last_received_ts = 268.051025
last_seq = 1341
current_ts = 268.161713
current_received_ts = 268.161377
current_seq = 1351
count = 59
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.051331/1341, current 268.161713/1351: elapsed=110378.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.051331/1341, current 268.161713/1351: elapsed=110378.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.161713
last_received_ts = 268.161377
last_seq = 1351
current_ts = 268.272095
current_received_ts = 268.271759
current_seq = 1361
count = 60
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.161713/1351, current 268.272095/1361: elapsed=110375.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.161713/1351, current 268.272095/1361: elapsed=110375.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.272095
last_received_ts = 268.271759
last_seq = 1361
current_ts = 268.382446
current_received_ts = 268.382141
current_seq = 1371
count = 61
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.272095/1361, current 268.382446/1371: elapsed=110377.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.272095/1361, current 268.382446/1371: elapsed=110377.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.382446
last_received_ts = 268.382141
last_seq = 1371
current_ts = 268.492828
current_received_ts = 268.492523
current_seq = 1381
count = 62
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.382446/1371, current 268.492828/1381: elapsed=110374.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.382446/1371, current 268.492828/1381: elapsed=110374.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.492828
last_received_ts = 268.492523
last_seq = 1381
current_ts = 268.603210
current_received_ts = 268.602905
current_seq = 1391
count = 63
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.492828/1381, current 268.603210/1391: elapsed=110376.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.492828/1381, current 268.603210/1391: elapsed=110376.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.603210
last_received_ts = 268.602905
last_seq = 1391
current_ts = 268.713593
current_received_ts = 268.713257
current_seq = 1401
count = 64
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.603210/1391, current 268.713593/1401: elapsed=110375.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.603210/1391, current 268.713593/1401: elapsed=110375.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.713593
last_received_ts = 268.713257
last_seq = 1401
current_ts = 268.823975
current_received_ts = 268.823639
current_seq = 1411
count = 65
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.713593/1401, current 268.823975/1411: elapsed=110376.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.713593/1401, current 268.823975/1411: elapsed=110376.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.823975
last_received_ts = 268.823639
last_seq = 1411
current_ts = 268.934326
current_received_ts = 268.934052
current_seq = 1421
count = 66
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.823975/1411, current 268.934326/1421: elapsed=110376.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.823975/1411, current 268.934326/1421: elapsed=110376.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 268.934326
last_received_ts = 268.934052
last_seq = 1421
current_ts = 269.044708
current_received_ts = 269.044403
current_seq = 1431
count = 67
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 268.934326/1421, current 269.044708/1431: elapsed=110386.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 268.934326/1421, current 269.044708/1431: elapsed=110386.0us expected=109321.9us
(kms_flip:2605) DEBUG: name = vblank
last_ts = 269.044708
last_received_ts = 269.044403
last_seq = 1431
current_ts = 269.155182
current_received_ts = 269.154846
current_seq = 1441
count = 68
seq_step = 10
(kms_flip:2605) DEBUG: vblank ts/seq: last 269.044708/1431, current 269.155182/1441: elapsed=110464.0us expected=109321.9us +- 546.6us, error 1.0%
(kms_flip:2605) DEBUG: inconsistent vblank ts/seq: last 269.044708/1431, current 269.155182/1441: elapsed=110464.0us expected=109321.9us
(kms_flip:2605) INFO: Event vblank: expected 694, counted 690, passrate = 33.33%, encoder type 2
(kms_flip:2605) DEBUG: dropped frames, expected 694, counted 690, passrate = 33.33%, encoder type 2
(kms_flip:2605) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1722:
(kms_flip:2605) CRITICAL: Failed assertion: !retried
(kms_flip:2605) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2605) igt_core-INFO: Stack trace:
(kms_flip:2605) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2605) igt_core-INFO:   #1 ../tests/kms_flip.c:1071 run_test_on_crtc_set()
(kms_flip:2605) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
(kms_flip:2605) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
(kms_flip:2605) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
(kms_flip:2605) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2605) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2605) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (20.998s)
Dmesg
<6> [279.880651] [IGT] kms_flip: starting dynamic subtest C-eDP1
<7> [279.881375] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem
<7> [279.881826] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:567]
<7> [279.882028] i915 0000:00:02.0: [drm:i915_dpt_create [i915]] Allocating dpt from smem
<7> [279.882511] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:568]
<7> [279.885639] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.885970] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.904357] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.904665] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.913446] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.913713] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.931400] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.931673] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [279.940098] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]
<7> [279.940372] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]
<7> [279.940437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.enable (expected yes, found no)
<7> [279.940598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.active (expected yes, found no)
<7> [279.940746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)
<7> [279.940884] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in lane_count (expected 4, found 0)
<7> [279.941020] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 623587/524288, found tu 0, data 0/0 link 0/0)
<7> [279.941167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [279.941301] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [279.941437] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [279.941572] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [279.941707] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [279.941844] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [279.941981] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [279.942130] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [279.942266] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [279.942402] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1801, found 0)
<7> [279.942536] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [279.942669] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [279.942797] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [279.942926] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [279.943054] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [279.943192] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [279.943323] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [279.943455] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [279.943584] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [279.943713] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [279.943846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [279.943978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1801, found 0)
<7> [279.944110] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [279.944251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [279.944383] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [279.944513] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [279.944644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [279.944776] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [279.944907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [279.945036] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [279.945173] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [279.945305] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [279.945436] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [279.945567] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in port_clock (expected 432000, found 0)
<7> [279.945698] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:269:pipe B] fastset requirement not met in set_context_latency (expected 1, found 0)
<7> [279.945829] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:269:pipe B] fastset requirement not met, forcing full modeset
<7> [279.945961] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:269:pipe B] releasing DPLL 0
<7> [279.946126] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [279.946257] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:269:pipe B] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x2 -> 0x0
<7> [279.946403] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:263:cursor B] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [279.946533] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:269:pipe B] min cdclk: 256910 kHz -> 0 kHz
<7> [279.946673] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing
<7> [279.946809] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [279.946946] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [279.947111] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:269:pipe B] enable: no [modeset]
<7> [279.947261] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:153:plane 1B] fb: [NOFB], visible: no
<7> [279.947397] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:183:plane 2B] fb: [NOFB], visible: no
<7> [279.947530] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:213:plane 3B] fb: [NOFB], visible: no
<7> [279.947665] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:243:plane 4B] fb: [NOFB], visible: no
<7> [279.947800] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:253:plane 5B] fb: [NOFB], visible: no
<7> [279.947936] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:263:cursor B] fb: [NOFB], visible: no
<7> [279.948184] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [280.152532] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 0
<7> [280.153479] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B
<7> [280.155848] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power off
<7> [280.156123] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [280.156407] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [280.156680] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - short
<7> [280.156965] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [280.207745] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [280.208355] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x2, on? 1) for [CRTC:269:pipe B]
<7> [280.208505] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:507:DDI A/PHY A]
<7> [280.208858] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [280.209412] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long
<7> [280.209932] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [280.210493] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0
<7> [280.210536] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]
<7> [280.211141] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [280.211770] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [280.212201] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B]
<7> [280.212575] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A]
<7> [280.212922] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B]
<7> [280.213256] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C]
<7> [280.213626] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D]
<7> [280.213962] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1]
<7> [280.214187] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A]
<7> [280.214364] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B]
<7> [280.214555] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C]
<7> [280.214751] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D]
<7> [280.214940] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2]
<7> [280.215157] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3]
<7> [280.215350] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [280.215549] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [280.215672] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [280.215797] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [280.215921] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4]
<7> [280.216043] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A]
<7> [280.216168] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B]
<7> [280.216299] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C]
<7> [280.216463] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D]
<7> [280.216649] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]
<7> [280.216922] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [280.217098] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [280.217242] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [280.217503] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_B
<7> [280.217655] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating disabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xaa000000)
<7> [280.217847] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2
<7> [280.218026] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:269:pipe B]
<7> [280.218237] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [280.218427] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [280.218849] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]
<7> [280.219030] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]
<7> [280.219150] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]
<7> [280.219182] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:508:eDP-1]
<7> [280.219247] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:508:eDP-1] Limiting target display pipe bpp to 24 (EDID bpp 30, max requested bpp 24, max platform bpp 36)
<7> [280.219417] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:507:DDI A/PHY A][CRTC:387:pipe C] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 24 min link_bpp 18.0000 max link_bpp 24.0000
<7> [280.219547] i915 0000:00:02.0: [drm:intel_dp_compute_output_format [i915]] DP lane count 4 clock 432000 bpp input 24 compressed 0.0000 HDR no link rate required 1541460 available 1728000
<7> [280.219676] i915 0000:00:02.0: [drm:intel_psr_compute_config [i915]] PSR2 not supported in transcoder C
<7> [280.219813] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [280.219949] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:507:DDI A/PHY A] [CRTC:387:pipe C]
<7> [280.220072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes)
<7> [280.220209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes)
<7> [280.220352] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)
<7> [280.220487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4)
<7> [280.220621] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 623587/524288)
<7> [280.220755] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [280.220888] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [280.221025] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [280.221158] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [280.221297] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [280.221429] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [280.221562] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [280.221694] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [280.221824] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [280.221955] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1801)
<7> [280.222086] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [280.222216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [280.222352] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [280.222480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [280.222608] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [280.222734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [280.222864] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [280.222994] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [280.223133] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [280.223262] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [280.223409] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [280.223546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1801)
<7> [280.223676] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [280.223804] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [280.223932] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [280.224058] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [280.224185] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [280.224318] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [280.224446] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [280.224573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [280.224699] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [280.224824] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [280.224951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [280.225079] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 432000)
<7> [280.225208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in set_context_latency (expected 0, found 1)
<7> [280.225345] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset
<7> [280.225492] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no
<7> [280.225618] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4
<7> [280.225764] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1953), size 0 -> 1953
<7> [280.225896] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1953 - 2048), size 0 -> 95
<7> [280.226037] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [280.226159] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0
<7> [280.226283] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197
<7> [280.226407] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198
<7> [280.226544] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe C] data rate 2055280 num active planes 1
<7> [280.226678] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [280.226807] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [280.226937] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [280.227067] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [280.227195] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [280.227343] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 256910 kHz
<7> [280.227481] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing
<7> [280.227606] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [280.227734] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [280.227872] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:387:pipe C] allocated DPLL 0
<7> [280.228006] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:387:pipe C] reserving DPLL 0
<7> [280.228139] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe C] enable: yes [modeset]
<7> [280.228272] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [280.228466] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0
<7> [280.228601] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [280.228730] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [280.228859] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [280.228990] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [280.229119] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 623587, link_n: 524288, tu: 64
<7> [280.229246] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [280.229384] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [280.229513] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [280.229646] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled
<7> [280.229776] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum hblank: 0
<7> [280.229902] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [280.230027] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 2, length 8
<7> [280.230153] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [280.230282] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [280.230410] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [280.230537] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [280.230663] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [280.230787] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [280.230913] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 1
<7> [280.231040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1878, vmax: 1878, flipline: 1878, pipeline full: 0, guardband: 76 vsync start: 75, vsync end: 69
<7> [280.231166] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1878, vmax vtotal: 1878
<7> [280.231319] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0
<7> [280.231445] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [280.231570] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [280.231694] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [280.231821] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa
<7> [280.231947] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [280.232073] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 432000, pixel rate 513820, min cdclk 256910, min voltage level 0
<7> [280.232198] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [280.232332] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0
<7> [280.232465] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 2880x1800+0+0
<7> [280.232597] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [280.232727] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [280.232852] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [280.232977] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no
<7> [280.233103] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: no,
<7> [280.233232] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] multiplier: 225, tx_clk_div: 1.
<7> [280.233370] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_rawhw_state:
<7> [280.233500] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] tx: 0x10, cmn: 0x21
<7> [280.233626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1
<7> [280.233752] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0
<7> [280.233876] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0
<7> [280.234016] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1
<7> [280.234171] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23
<7> [280.234311] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [280.234442] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [280.234572] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [280.234703] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.234836] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.234964] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.235091] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [280.235216] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [280.235355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.235490] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.235621] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [280.235753] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [280.235886] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1C] fb: [FB:567] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes
<7> [280.236018] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [280.236148] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [280.236288] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2C] fb: [NOFB], visible: no
<7> [280.236422] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3C] fb: [NOFB], visible: no
<7> [280.236551] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4C] fb: [NOFB], visible: no
<7> [280.236676] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5C] fb: [NOFB], visible: no
<7> [280.236834] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor C] fb: [NOFB], visible: no
<7> [280.237573] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [280.237919] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [280.238336] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<7> [280.239599] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [280.239905] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [280.240124] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [280.240295] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_C
<7> [280.240486] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000)
<7> [280.240647] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [280.240821] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [280.240957] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [280.241088] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B]
<7> [280.241219] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A]
<7> [280.241365] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B]
<7> [280.241498] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C]
<7> [280.241631] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D]
<7> [280.241763] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1]
<7> [280.241895] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A]
<7> [280.242028] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B]
<7> [280.242166] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C]
<7> [280.242307] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D]
<7> [280.242436] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2]
<7> [280.242566] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3]
<7> [280.242696] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [280.242824] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [280.242952] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [280.243083] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [280.243215] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4]
<7> [280.243353] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A]
<7> [280.243482] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B]
<7> [280.243613] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C]
<7> [280.243745] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D]
<7> [280.243907] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xd
<7> [280.244144] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [280.244363] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [280.245343] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:387:pipe C]
<7> [280.245527] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0
<7> [280.247704] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power on
<7> [280.247864] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power cycle (461 ms remaining)
<7> [280.712909] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060
<7> [280.773962] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [280.774509] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power on
<7> [280.775089] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [280.806598] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [280.807157] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long
<7> [280.807682] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [280.808283] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]
<7> [280.981337] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [280.982197] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD on
<7> [280.982838] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [280.986171] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80
<7> [280.987816] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [280.988525] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 06
<7> [280.989607] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [280.990696] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [280.991681] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Clock recovery OK
<7> [280.991817] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [280.993076] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [280.993196] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4
<7> [280.993924] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C
<7> [280.994223] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [280.994343] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe C
<7> [280.994532] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 13892
<7> [281.005469] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR1
<7> [281.006656] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]
<7> [281.006870] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe C]
<7> [283.554165] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD off
<7> [283.554540] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [291.835795] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]
<7> [291.836460] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:269:pipe B]
<7> [291.836783] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]
<7> [291.837008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected yes, found no)
<7> [291.837812] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected yes, found no)
<7> [291.838501] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected 2, found -1)
<7> [291.839072] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 4, found 0)
<7> [291.839498] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 623587/524288, found tu 0, data 0/0 link 0/0)
<7> [291.839889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [291.840423] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [291.840809] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [291.841013] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [291.841263] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [291.841617] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [291.841949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [291.842324] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [291.842528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [291.842686] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1801, found 0)
<7> [291.842838] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [291.842979] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [291.843122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [291.843279] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [291.843420] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [291.843555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [291.843691] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [291.843824] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [291.843956] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [291.844088] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [291.844225] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [291.844371] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1801, found 0)
<7> [291.844507] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [291.844642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [291.844775] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [291.844907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [291.845042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [291.845178] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [291.845318] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [291.845455] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [291.845589] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [291.845721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [291.845853] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [291.845988] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 432000, found 0)
<7> [291.846126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in set_context_latency (expected 1, found 0)
<7> [291.846261] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset
<7> [291.846403] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:387:pipe C] releasing DPLL 0
<7> [291.846557] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xd -> 0x1 (total dbuf slices 0xf), mbus joined? no->no
<7> [291.846691] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe C] dbuf slices 0xc -> 0x0, ddb (0 - 2048) -> (0 - 0), active pipes 0x4 -> 0x0
<7> [291.846848] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1C] ddb ( 0 - 1953) -> ( 0 - 0), size 1953 -> 0
<7> [291.846979] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor C] ddb (1953 - 2048) -> ( 0 - 0), size 95 -> 0
<7> [291.847106] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [291.847234] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] lines 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [291.847368] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] blocks 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [291.847495] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] min_ddb 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [291.847638] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe C] data rate 0 num active planes 0
<7> [291.847780] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [291.847918] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [291.848055] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [291.848192] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [291.848328] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [291.848492] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe C] min cdclk: 256910 kHz -> 0 kHz
<7> [291.848641] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 32114 kHz -> 0 kHz
<7> [291.848778] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing
<7> [291.848914] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [291.849048] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [291.849201] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe C] enable: no [modeset]
<7> [291.849337] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1C] fb: [NOFB], visible: no
<7> [291.849487] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2C] fb: [NOFB], visible: no
<7> [291.849624] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3C] fb: [NOFB], visible: no
<7> [291.849761] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4C] fb: [NOFB], visible: no
<7> [291.849896] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5C] fb: [NOFB], visible: no
<7> [291.850029] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor C] fb: [NOFB], visible: no
<7> [291.850207] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR1
<7> [291.856832] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD on
<7> [291.857107] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f
<7> [291.857702] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [292.063502] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 0
<7> [292.064352] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe C
<7> [292.068105] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power off
<7> [292.068708] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [292.069195] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [292.120059] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [292.120731] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable DPLL 0 (active 0x4, on? 1) for [CRTC:387:pipe C]
<7> [292.121194] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [292.121770] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long
<7> [292.122290] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [292.122701] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling DPLL 0
<7> [292.122887] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]
<7> [292.123380] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [292.124057] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [292.124504] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B]
<7> [292.124836] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A]
<7> [292.125160] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B]
<7> [292.125497] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C]
<7> [292.125775] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D]
<7> [292.126113] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1]
<7> [292.126479] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A]
<7> [292.126741] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B]
<7> [292.126949] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C]
<7> [292.127086] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D]
<7> [292.127214] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2]
<7> [292.127341] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3]
<7> [292.127468] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [292.127609] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [292.127735] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [292.127861] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [292.127986] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4]
<7> [292.128112] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A]
<7> [292.128267] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B]
<7> [292.128395] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C]
<7> [292.128530] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D]
<7> [292.128657] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]
<7> [292.128844] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [292.129017] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [292.129268] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_C
<7> [292.129417] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating disabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0xaa000000)
<7> [292.129615] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_2
<7> [292.129787] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe C]
<7> [292.129971] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [292.130145] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [292.130503] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:505:pipe D]
<7> [292.130669] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:387:pipe C]
<7> [292.130694] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:508:eDP-1]
<7> [292.130751] i915 0000:00:02.0: [drm:compute_baseline_pipe_bpp [i915]] [CONNECTOR:508:eDP-1] Limiting target display pipe bpp to 24 (EDID bpp 30, max requested bpp 24, max platform bpp 36)
<7> [292.130897] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:507:DDI A/PHY A][CRTC:387:pipe C] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 24 min link_bpp 18.0000 max link_bpp 24.0000
<7> [292.131023] i915 0000:00:02.0: [drm:intel_dp_compute_output_format [i915]] DP lane count 4 clock 432000 bpp input 24 compressed 0.0000 HDR no link rate required 1541460 available 1728000
<7> [292.131147] i915 0000:00:02.0: [drm:intel_psr_compute_config [i915]] PSR2 not supported in transcoder C
<7> [292.131286] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe C] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [292.131426] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:507:DDI A/PHY A] [CRTC:387:pipe C]
<7> [292.131557] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.enable (expected no, found yes)
<7> [292.131694] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.active (expected no, found yes)
<7> [292.131831] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in cpu_transcoder (expected -1, found 2)
<7> [292.131968] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in lane_count (expected 0, found 4)
<7> [292.132113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 623587/524288)
<7> [292.132268] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [292.132452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [292.132600] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [292.132744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [292.132874] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [292.133007] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [292.133141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [292.133275] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [292.133408] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [292.133539] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1801)
<7> [292.133682] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [292.133816] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [292.133948] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [292.134079] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [292.134211] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [292.134343] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [292.134474] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [292.134611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [292.134744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [292.134876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [292.135009] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [292.135140] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1801)
<7> [292.135271] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [292.135401] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [292.135533] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [292.135674] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [292.135807] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [292.135940] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [292.136071] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [292.136204] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [292.136339] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [292.136470] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [292.136601] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [292.136744] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in port_clock (expected 0, found 432000)
<7> [292.136875] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:387:pipe C] fastset requirement not met in set_context_latency (expected 0, found 1)
<7> [292.137004] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:387:pipe C] fastset requirement not met, forcing full modeset
<7> [292.137153] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xd (total dbuf slices 0xf), mbus joined? no->no
<7> [292.137281] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:387:pipe C] dbuf slices 0x0 -> 0xc, ddb (0 - 0) -> (0 - 2048), active pipes 0x0 -> 0x4
<7> [292.137425] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:271:plane 1C] ddb ( 0 - 0) -> ( 0 - 1953), size 0 -> 1953
<7> [292.137551] i915 0000:00:02.0: [drm:skl_print_plane_ddb_changes [i915]] [PLANE:381:cursor C] ddb ( 0 - 0) -> (1953 - 2048), size 0 -> 95
<7> [292.137681] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [292.137807] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 16, 16, 19, 19, 28, 0, 0, 0, 4, 0
<7> [292.137938] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 365, 365, 434, 434, 638, 0, 0, 197, 92, 197
<7> [292.138064] i915 0000:00:02.0: [drm:skl_print_plane_wm_changes [i915]] [PLANE:271:plane 1C] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 547, 547, 729, 0, 0, 198, 183, 198
<7> [292.138200] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:387:pipe C] data rate 2055280 num active planes 1
<7> [292.138337] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [292.138474] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [292.138610] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [292.138752] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [292.138886] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [292.139033] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:387:pipe C] min cdclk: 0 kHz -> 256910 kHz
<7> [292.139177] i915 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [i915]] dbuf bandwidth min cdclk: 0 kHz -> 32114 kHz
<7> [292.139311] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] Can change cdclk via squashing
<7> [292.139443] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [292.139575] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] New voltage level calculated to be logical 0, actual 0
<7> [292.139723] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:387:pipe C] allocated DPLL 0
<7> [292.139859] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:387:pipe C] reserving DPLL 0
<7> [292.139997] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:387:pipe C] enable: yes [modeset]
<7> [292.140135] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [292.140269] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: C, pipe bpp: 24, dithering: 0
<7> [292.140402] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [292.140535] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [292.140672] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [292.140825] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [292.140962] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 623587, link_n: 524288, tu: 64
<7> [292.141093] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [292.141223] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [292.141355] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [292.141487] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: disabled, panel replay: disabled, selective fetch: disabled
<7> [292.141618] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum hblank: 0
<7> [292.141755] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [292.141885] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 2, length 8
<7> [292.142014] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [292.142145] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [292.142277] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [292.142406] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [292.142537] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [292.142666] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [292.142805] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 1
<7> [292.142938] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: yes, vmin: 1878, vmax: 1878, flipline: 1878, pipeline full: 0, guardband: 76 vsync start: 75, vsync end: 69
<7> [292.143072] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1878, vmax vtotal: 1878
<7> [292.143203] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0
<7> [292.143336] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [292.143472] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [292.143611] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [292.143741] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa
<7> [292.143885] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1801-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [292.144020] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 432000, pixel rate 513820, min cdclk 256910, min voltage level 0
<7> [292.144153] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [292.144286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0
<7> [292.144416] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 2880x1800+0+0
<7> [292.144546] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [292.144675] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0
<7> [292.144816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [292.144947] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no
<7> [292.145078] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_hw_state: fracen: no,
<7> [292.145209] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] multiplier: 225, tx_clk_div: 1.
<7> [292.145340] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] c10pll_rawhw_state:
<7> [292.145471] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] tx: 0x10, cmn: 0x21
<7> [292.145605] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1
<7> [292.145737] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0
<7> [292.145876] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0
<7> [292.146006] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1
<7> [292.146136] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23
<7> [292.146271] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [292.146411] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [292.146546] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [292.146679] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.146812] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.146956] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.147091] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [292.147226] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [292.147361] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.147494] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.147626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [292.147757] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [292.147943] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:271:plane 1C] fb: [FB:567] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes
<7> [292.148082] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [292.148218] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [292.148353] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:301:plane 2C] fb: [NOFB], visible: no
<7> [292.148487] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:331:plane 3C] fb: [NOFB], visible: no
<7> [292.148620] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:361:plane 4C] fb: [NOFB], visible: no
<7> [292.148756] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:371:plane 5C] fb: [NOFB], visible: no
<7> [292.148904] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:381:cursor C] fb: [NOFB], visible: no
<7> [292.148930] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [292.149138] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [292.149292] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<7> [292.149495] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [292.149646] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [292.149785] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [292.150080] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [292.150291] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [292.150450] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_C
<7> [292.150634] i915 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [i915]] DSS clock gating enabled for pipe_mask=0x4 (CLKGATE_DIS_DSSDSC=0x8a000000)
<7> [292.150793] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [292.150977] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [292.151113] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:507:DDI A/PHY A]
<7> [292.151248] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:516:DDI B/PHY B]
<7> [292.151379] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:518:DP-MST A]
<7> [292.151511] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:519:DP-MST B]
<7> [292.151642] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:520:DP-MST C]
<7> [292.151771] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:521:DP-MST D]
<7> [292.151898] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:534:DDI TC1/PHY TC1]
<7> [292.152040] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:536:DP-MST A]
<7> [292.152172] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:537:DP-MST B]
<7> [292.152301] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:538:DP-MST C]
<7> [292.152428] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:539:DP-MST D]
<7> [292.152555] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:543:DDI TC2/PHY TC2]
<7> [292.152681] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:547:DDI TC3/PHY TC3]
<7> [292.152810] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:549:DP-MST A]
<7> [292.152941] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:550:DP-MST B]
<7> [292.153076] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:551:DP-MST C]
<7> [292.153207] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:552:DP-MST D]
<7> [292.153340] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:556:DDI TC4/PHY TC4]
<7> [292.153473] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:558:DP-MST A]
<7> [292.153606] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:559:DP-MST B]
<7> [292.153739] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:560:DP-MST C]
<7> [292.153870] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:561:DP-MST D]
<7> [292.154042] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xd
<7> [292.154281] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [292.154498] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [292.155877] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable DPLL 0 (active 0x4, on? 0) for [CRTC:387:pipe C]
<7> [292.156077] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling DPLL 0
<7> [292.158229] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turn panel power on
<7> [292.158389] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power cycle (463 ms remaining)
<7> [292.633790] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060
<7> [292.672011] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [292.672607] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 wait for panel power on
<7> [292.673119] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [292.704681] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [292.705249] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:507:DDI A/PHY A] - long
<7> [292.705772] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [292.706304] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:507:DDI A/PHY A]
<7> [292.878189] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [292.880108] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD on
<7> [292.880712] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [292.884008] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80
<7> [292.885610] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [292.886278] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 06
<7> [292.887314] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [292.888306] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [292.889217] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Clock recovery OK
<7> [292.889347] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [292.890724] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [292.890850] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:508:eDP-1][ENCODER:507:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4
<7> [292.891569] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe C
<7> [292.891859] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [292.891987] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe C
<7> [292.892162] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:508:eDP-1] set backlight PWM = 13892
<7> [292.903020] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR1
<7> [292.904292] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:508:eDP-1]
<7> [292.904516] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:387:pipe C]
<7> [295.498467] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 turning VDD off
<7> [295.499095] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:507:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<6> [300.882051] [IGT] kms_flip: finished subtest C-eDP1, FAIL
Created at 2026-04-26 22:48:16