Results for igt@kms_flip@plain-flip-ts-check@a-edp1

Machine description: shard-mtlp-4

Result: Fail

git-log-oneline i915_display_info12 igt_runner12 runtimes12 results12.json results12-i915-load.json i915_display_info_post_exec12 boot12 dmesg12

DetailValue
Duration 10.16 seconds
Hostname 
shard-mtlp-4
Igt-Version 
IGT-Version: 2.0-g49d989682 (x86_64) (Linux: 6.14.0-rc7-CI_DRM_16299-gb15a87713d14+ x86_64)
Out 
Using IGT_SRANDOM=1742569502 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11211.3us +- 2.750us accuracy 0.07%
vblank interval differs from modeline! expected 11111.1us, measured 11211us +- 2.750us, difference 100.2us (36.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (10.164s)
Err 
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
(kms_flip:2435) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2435) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2435) DEBUG: flip ts/seq: last 194.625458/5768, current 194.636627/5769: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.636627
last_received_ts = 194.636368
last_seq = 5769
current_ts = 194.647797
current_received_ts = 194.647659
current_seq = 5770
count = 389
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.636627/5769, current 194.647797/5770: elapsed=11176.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.647797
last_received_ts = 194.647659
last_seq = 5770
current_ts = 194.658981
current_received_ts = 194.658875
current_seq = 5771
count = 390
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.647797/5770, current 194.658981/5771: elapsed=11175.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.658981
last_received_ts = 194.658875
last_seq = 5771
current_ts = 194.670151
current_received_ts = 194.670105
current_seq = 5772
count = 391
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.658981/5771, current 194.670151/5772: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.670151
last_received_ts = 194.670105
last_seq = 5772
current_ts = 194.681320
current_received_ts = 194.681168
current_seq = 5773
count = 392
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.670151/5772, current 194.681320/5773: elapsed=11172.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.681320
last_received_ts = 194.681168
last_seq = 5773
current_ts = 194.692490
current_received_ts = 194.692444
current_seq = 5774
count = 393
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.681320/5773, current 194.692490/5774: elapsed=11174.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.692490
last_received_ts = 194.692444
last_seq = 5774
current_ts = 194.703659
current_received_ts = 194.703476
current_seq = 5775
count = 394
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.692490/5774, current 194.703659/5775: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.703659
last_received_ts = 194.703476
last_seq = 5775
current_ts = 194.714828
current_received_ts = 194.714691
current_seq = 5776
count = 395
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.703659/5775, current 194.714828/5776: elapsed=11172.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.714828
last_received_ts = 194.714691
last_seq = 5776
current_ts = 194.726013
current_received_ts = 194.725906
current_seq = 5777
count = 396
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.714828/5776, current 194.726013/5777: elapsed=11175.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.726013
last_received_ts = 194.725906
last_seq = 5777
current_ts = 194.737183
current_received_ts = 194.737076
current_seq = 5778
count = 397
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.726013/5777, current 194.737183/5778: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.737183
last_received_ts = 194.737076
last_seq = 5778
current_ts = 194.748352
current_received_ts = 194.748199
current_seq = 5779
count = 398
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.737183/5778, current 194.748352/5779: elapsed=11173.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.748352
last_received_ts = 194.748199
last_seq = 5779
current_ts = 194.759521
current_received_ts = 194.759399
current_seq = 5780
count = 399
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.748352/5779, current 194.759521/5780: elapsed=11176.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.759521
last_received_ts = 194.759399
last_seq = 5780
current_ts = 194.770691
current_received_ts = 194.770493
current_seq = 5781
count = 400
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.759521/5780, current 194.770691/5781: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.770691
last_received_ts = 194.770493
last_seq = 5781
current_ts = 194.781860
current_received_ts = 194.781830
current_seq = 5782
count = 401
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.770691/5781, current 194.781860/5782: elapsed=11171.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.781860
last_received_ts = 194.781830
last_seq = 5782
current_ts = 194.793045
current_received_ts = 194.792984
current_seq = 5783
count = 402
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.781860/5782, current 194.793045/5783: elapsed=11177.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.793045
last_received_ts = 194.792984
last_seq = 5783
current_ts = 194.804214
current_received_ts = 194.804108
current_seq = 5784
count = 403
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.793045/5783, current 194.804214/5784: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.804214
last_received_ts = 194.804108
last_seq = 5784
current_ts = 194.815384
current_received_ts = 194.815186
current_seq = 5785
count = 404
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.804214/5784, current 194.815384/5785: elapsed=11173.0us expected=11211.3us +- 56.1us, error 0.3%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.815384
last_received_ts = 194.815186
last_seq = 5785
current_ts = 194.826553
current_received_ts = 194.826370
current_seq = 5786
count = 405
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.815384/5785, current 194.826553/5786: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.826553
last_received_ts = 194.826370
last_seq = 5786
current_ts = 194.837708
current_received_ts = 194.837585
current_seq = 5787
count = 406
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.826553/5786, current 194.837708/5787: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.837708
last_received_ts = 194.837585
last_seq = 5787
current_ts = 194.848877
current_received_ts = 194.848679
current_seq = 5788
count = 407
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.837708/5787, current 194.848877/5788: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.848877
last_received_ts = 194.848679
last_seq = 5788
current_ts = 194.860046
current_received_ts = 194.859955
current_seq = 5789
count = 408
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.848877/5788, current 194.860046/5789: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.860046
last_received_ts = 194.859955
last_seq = 5789
current_ts = 194.871216
current_received_ts = 194.871140
current_seq = 5790
count = 409
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.860046/5789, current 194.871216/5790: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.871216
last_received_ts = 194.871140
last_seq = 5790
current_ts = 194.882370
current_received_ts = 194.882217
current_seq = 5791
count = 410
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.871216/5790, current 194.882370/5791: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.882370
last_received_ts = 194.882217
last_seq = 5791
current_ts = 194.893539
current_received_ts = 194.893341
current_seq = 5792
count = 411
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.882370/5791, current 194.893539/5792: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.893539
last_received_ts = 194.893341
last_seq = 5792
current_ts = 194.904709
current_received_ts = 194.904510
current_seq = 5793
count = 412
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.893539/5792, current 194.904709/5793: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.904709
last_received_ts = 194.904510
last_seq = 5793
current_ts = 194.915878
current_received_ts = 194.915802
current_seq = 5794
count = 413
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.904709/5793, current 194.915878/5794: elapsed=11171.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.915878
last_received_ts = 194.915802
last_seq = 5794
current_ts = 194.927032
current_received_ts = 194.926956
current_seq = 5795
count = 414
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.915878/5794, current 194.927032/5795: elapsed=11161.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.927032
last_received_ts = 194.926956
last_seq = 5795
current_ts = 194.938202
current_received_ts = 194.938095
current_seq = 5796
count = 415
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.927032/5795, current 194.938202/5796: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.938202
last_received_ts = 194.938095
last_seq = 5796
current_ts = 194.949371
current_received_ts = 194.949280
current_seq = 5797
count = 416
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.938202/5796, current 194.949371/5797: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.949371
last_received_ts = 194.949280
last_seq = 5797
current_ts = 194.960526
current_received_ts = 194.960403
current_seq = 5798
count = 417
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.949371/5797, current 194.960526/5798: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.960526
last_received_ts = 194.960403
last_seq = 5798
current_ts = 194.971695
current_received_ts = 194.971512
current_seq = 5799
count = 418
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.960526/5798, current 194.971695/5799: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.971695
last_received_ts = 194.971512
last_seq = 5799
current_ts = 194.982864
current_received_ts = 194.982819
current_seq = 5800
count = 419
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.971695/5799, current 194.982864/5800: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.982864
last_received_ts = 194.982819
last_seq = 5800
current_ts = 194.994034
current_received_ts = 194.993759
current_seq = 5801
count = 420
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.982864/5800, current 194.994034/5801: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 194.994034
last_received_ts = 194.993759
last_seq = 5801
current_ts = 195.005203
current_received_ts = 195.005112
current_seq = 5802
count = 421
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 194.994034/5801, current 195.005203/5802: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.005203
last_received_ts = 195.005112
last_seq = 5802
current_ts = 195.016357
current_received_ts = 195.016220
current_seq = 5803
count = 422
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.005203/5802, current 195.016357/5803: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.016357
last_received_ts = 195.016220
last_seq = 5803
current_ts = 195.027527
current_received_ts = 195.027374
current_seq = 5804
count = 423
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.016357/5803, current 195.027527/5804: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.027527
last_received_ts = 195.027374
last_seq = 5804
current_ts = 195.038696
current_received_ts = 195.038498
current_seq = 5805
count = 424
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.027527/5804, current 195.038696/5805: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.038696
last_received_ts = 195.038498
last_seq = 5805
current_ts = 195.049850
current_received_ts = 195.049774
current_seq = 5806
count = 425
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.038696/5805, current 195.049850/5806: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.049850
last_received_ts = 195.049774
last_seq = 5806
current_ts = 195.061020
current_received_ts = 195.060959
current_seq = 5807
count = 426
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.049850/5806, current 195.061020/5807: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.061020
last_received_ts = 195.060959
last_seq = 5807
current_ts = 195.072189
current_received_ts = 195.072067
current_seq = 5808
count = 427
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.061020/5807, current 195.072189/5808: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.072189
last_received_ts = 195.072067
last_seq = 5808
current_ts = 195.083344
current_received_ts = 195.083221
current_seq = 5809
count = 428
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.072189/5808, current 195.083344/5809: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.083344
last_received_ts = 195.083221
last_seq = 5809
current_ts = 195.094513
current_received_ts = 195.094345
current_seq = 5810
count = 429
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.083344/5809, current 195.094513/5810: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.094513
last_received_ts = 195.094345
last_seq = 5810
current_ts = 195.105682
current_received_ts = 195.105484
current_seq = 5811
count = 430
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.094513/5810, current 195.105682/5811: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.105682
last_received_ts = 195.105484
last_seq = 5811
current_ts = 195.116852
current_received_ts = 195.116760
current_seq = 5812
count = 431
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.105682/5811, current 195.116852/5812: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.116852
last_received_ts = 195.116760
last_seq = 5812
current_ts = 195.128021
current_received_ts = 195.127930
current_seq = 5813
count = 432
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.116852/5812, current 195.128021/5813: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.128021
last_received_ts = 195.127930
last_seq = 5813
current_ts = 195.139175
current_received_ts = 195.139069
current_seq = 5814
count = 433
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.128021/5813, current 195.139175/5814: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.139175
last_received_ts = 195.139069
last_seq = 5814
current_ts = 195.150345
current_received_ts = 195.150192
current_seq = 5815
count = 434
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.139175/5814, current 195.150345/5815: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.150345
last_received_ts = 195.150192
last_seq = 5815
current_ts = 195.161514
current_received_ts = 195.161392
current_seq = 5816
count = 435
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.150345/5815, current 195.161514/5816: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.161514
last_received_ts = 195.161392
last_seq = 5816
current_ts = 195.172668
current_received_ts = 195.172501
current_seq = 5817
count = 436
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.161514/5816, current 195.172668/5817: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.172668
last_received_ts = 195.172501
last_seq = 5817
current_ts = 195.183838
current_received_ts = 195.183762
current_seq = 5818
count = 437
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.172668/5817, current 195.183838/5818: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.183838
last_received_ts = 195.183762
last_seq = 5818
current_ts = 195.195007
current_received_ts = 195.194916
current_seq = 5819
count = 438
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.183838/5818, current 195.195007/5819: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.195007
last_received_ts = 195.194916
last_seq = 5819
current_ts = 195.206177
current_received_ts = 195.206131
current_seq = 5820
count = 439
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.195007/5819, current 195.206177/5820: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.206177
last_received_ts = 195.206131
last_seq = 5820
current_ts = 195.217331
current_received_ts = 195.217438
current_seq = 5821
count = 440
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.206177/5820, current 195.217331/5821: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.217331
last_received_ts = 195.217438
last_seq = 5821
current_ts = 195.228500
current_received_ts = 195.228622
current_seq = 5822
count = 441
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.217331/5821, current 195.228500/5822: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.228500
last_received_ts = 195.228622
last_seq = 5822
current_ts = 195.239670
current_received_ts = 195.239487
current_seq = 5823
count = 442
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.228500/5822, current 195.239670/5823: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.239670
last_received_ts = 195.239487
last_seq = 5823
current_ts = 195.250839
current_received_ts = 195.250763
current_seq = 5824
count = 443
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.239670/5823, current 195.250839/5824: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.250839
last_received_ts = 195.250763
last_seq = 5824
current_ts = 195.261993
current_received_ts = 195.261932
current_seq = 5825
count = 444
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.250839/5824, current 195.261993/5825: elapsed=11161.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.261993
last_received_ts = 195.261932
last_seq = 5825
current_ts = 195.273163
current_received_ts = 195.273117
current_seq = 5826
count = 445
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.261993/5825, current 195.273163/5826: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.273163
last_received_ts = 195.273117
last_seq = 5826
current_ts = 195.284332
current_received_ts = 195.284180
current_seq = 5827
count = 446
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.273163/5826, current 195.284332/5827: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.284332
last_received_ts = 195.284180
last_seq = 5827
current_ts = 195.295486
current_received_ts = 195.295319
current_seq = 5828
count = 447
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.284332/5827, current 195.295486/5828: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.295486
last_received_ts = 195.295319
last_seq = 5828
current_ts = 195.306656
current_received_ts = 195.306473
current_seq = 5829
count = 448
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.295486/5828, current 195.306656/5829: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.306656
last_received_ts = 195.306473
last_seq = 5829
current_ts = 195.317825
current_received_ts = 195.317657
current_seq = 5830
count = 449
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.306656/5829, current 195.317825/5830: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.317825
last_received_ts = 195.317657
last_seq = 5830
current_ts = 195.328979
current_received_ts = 195.328903
current_seq = 5831
count = 450
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.317825/5830, current 195.328979/5831: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.328979
last_received_ts = 195.328903
last_seq = 5831
current_ts = 195.340149
current_received_ts = 195.340088
current_seq = 5832
count = 451
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.328979/5831, current 195.340149/5832: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.340149
last_received_ts = 195.340088
last_seq = 5832
current_ts = 195.351318
current_received_ts = 195.351196
current_seq = 5833
count = 452
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.340149/5832, current 195.351318/5833: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.351318
last_received_ts = 195.351196
last_seq = 5833
current_ts = 195.362488
current_received_ts = 195.362350
current_seq = 5834
count = 453
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.351318/5833, current 195.362488/5834: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.362488
last_received_ts = 195.362350
last_seq = 5834
current_ts = 195.373642
current_received_ts = 195.373474
current_seq = 5835
count = 454
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.362488/5834, current 195.373642/5835: elapsed=11161.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.373642
last_received_ts = 195.373474
last_seq = 5835
current_ts = 195.384811
current_received_ts = 195.384750
current_seq = 5836
count = 455
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.373642/5835, current 195.384811/5836: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.384811
last_received_ts = 195.384750
last_seq = 5836
current_ts = 195.395981
current_received_ts = 195.395905
current_seq = 5837
count = 456
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.384811/5836, current 195.395981/5837: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.395981
last_received_ts = 195.395905
last_seq = 5837
current_ts = 195.407150
current_received_ts = 195.407074
current_seq = 5838
count = 457
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.395981/5837, current 195.407150/5838: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.407150
last_received_ts = 195.407074
last_seq = 5838
current_ts = 195.418304
current_received_ts = 195.418182
current_seq = 5839
count = 458
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.407150/5838, current 195.418304/5839: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.418304
last_received_ts = 195.418182
last_seq = 5839
current_ts = 195.429474
current_received_ts = 195.429260
current_seq = 5840
count = 459
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.418304/5839, current 195.429474/5840: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.429474
last_received_ts = 195.429260
last_seq = 5840
current_ts = 195.440643
current_received_ts = 195.440460
current_seq = 5841
count = 460
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.429474/5840, current 195.440643/5841: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.440643
last_received_ts = 195.440460
last_seq = 5841
current_ts = 195.451797
current_received_ts = 195.451630
current_seq = 5842
count = 461
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.440643/5841, current 195.451797/5842: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.451797
last_received_ts = 195.451630
last_seq = 5842
current_ts = 195.462967
current_received_ts = 195.462891
current_seq = 5843
count = 462
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.451797/5842, current 195.462967/5843: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.462967
last_received_ts = 195.462891
last_seq = 5843
current_ts = 195.474136
current_received_ts = 195.474075
current_seq = 5844
count = 463
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.462967/5843, current 195.474136/5844: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.474136
last_received_ts = 195.474075
last_seq = 5844
current_ts = 195.485306
current_received_ts = 195.485245
current_seq = 5845
count = 464
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.474136/5844, current 195.485306/5845: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.485306
last_received_ts = 195.485245
last_seq = 5845
current_ts = 195.496475
current_received_ts = 195.496368
current_seq = 5846
count = 465
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.485306/5845, current 195.496475/5846: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.496475
last_received_ts = 195.496368
last_seq = 5846
current_ts = 195.507629
current_received_ts = 195.507431
current_seq = 5847
count = 466
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.496475/5846, current 195.507629/5847: elapsed=11161.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.507629
last_received_ts = 195.507431
last_seq = 5847
current_ts = 195.518799
current_received_ts = 195.518738
current_seq = 5848
count = 467
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.507629/5847, current 195.518799/5848: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.518799
last_received_ts = 195.518738
last_seq = 5848
current_ts = 195.529968
current_received_ts = 195.529938
current_seq = 5849
count = 468
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.518799/5848, current 195.529968/5849: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.529968
last_received_ts = 195.529938
last_seq = 5849
current_ts = 195.541122
current_received_ts = 195.541077
current_seq = 5850
count = 469
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.529968/5849, current 195.541122/5850: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.541122
last_received_ts = 195.541077
last_seq = 5850
current_ts = 195.552292
current_received_ts = 195.552170
current_seq = 5851
count = 470
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.541122/5850, current 195.552292/5851: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.552292
last_received_ts = 195.552170
last_seq = 5851
current_ts = 195.563461
current_received_ts = 195.563370
current_seq = 5852
count = 471
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.552292/5851, current 195.563461/5852: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.563461
last_received_ts = 195.563370
last_seq = 5852
current_ts = 195.574631
current_received_ts = 195.574432
current_seq = 5853
count = 472
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.563461/5852, current 195.574631/5853: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.574631
last_received_ts = 195.574432
last_seq = 5853
current_ts = 195.585785
current_received_ts = 195.585648
current_seq = 5854
count = 473
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.574631/5853, current 195.585785/5854: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.585785
last_received_ts = 195.585648
last_seq = 5854
current_ts = 195.596954
current_received_ts = 195.596893
current_seq = 5855
count = 474
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.585785/5854, current 195.596954/5855: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.596954
last_received_ts = 195.596893
last_seq = 5855
current_ts = 195.608124
current_received_ts = 195.608078
current_seq = 5856
count = 475
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.596954/5855, current 195.608124/5856: elapsed=11170.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.608124
last_received_ts = 195.608078
last_seq = 5856
current_ts = 195.619293
current_received_ts = 195.619125
current_seq = 5857
count = 476
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.608124/5856, current 195.619293/5857: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.619293
last_received_ts = 195.619125
last_seq = 5857
current_ts = 195.630447
current_received_ts = 195.630234
current_seq = 5858
count = 477
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.619293/5857, current 195.630447/5858: elapsed=11160.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.630447
last_received_ts = 195.630234
last_seq = 5858
current_ts = 195.641617
current_received_ts = 195.641449
current_seq = 5859
count = 478
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.630447/5858, current 195.641617/5859: elapsed=11169.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.641617
last_received_ts = 195.641449
last_seq = 5859
current_ts = 195.652786
current_received_ts = 195.652618
current_seq = 5860
count = 479
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.641617/5859, current 195.652786/5860: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.652786
last_received_ts = 195.652618
last_seq = 5860
current_ts = 195.663940
current_received_ts = 195.663864
current_seq = 5861
count = 480
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.652786/5860, current 195.663940/5861: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.663940
last_received_ts = 195.663864
last_seq = 5861
current_ts = 195.675110
current_received_ts = 195.675034
current_seq = 5862
count = 481
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.663940/5861, current 195.675110/5862: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.675110
last_received_ts = 195.675034
last_seq = 5862
current_ts = 195.686279
current_received_ts = 195.686172
current_seq = 5863
count = 482
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.675110/5862, current 195.686279/5863: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.686279
last_received_ts = 195.686172
last_seq = 5863
current_ts = 195.697433
current_received_ts = 195.697296
current_seq = 5864
count = 483
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.686279/5863, current 195.697433/5864: elapsed=11164.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.697433
last_received_ts = 195.697296
last_seq = 5864
current_ts = 195.708603
current_received_ts = 195.708435
current_seq = 5865
count = 484
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.697433/5864, current 195.708603/5865: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.708603
last_received_ts = 195.708435
last_seq = 5865
current_ts = 195.719772
current_received_ts = 195.719620
current_seq = 5866
count = 485
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.708603/5865, current 195.719772/5866: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.719772
last_received_ts = 195.719620
last_seq = 5866
current_ts = 195.730942
current_received_ts = 195.730850
current_seq = 5867
count = 486
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.719772/5866, current 195.730942/5867: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.730942
last_received_ts = 195.730850
last_seq = 5867
current_ts = 195.742096
current_received_ts = 195.742081
current_seq = 5868
count = 487
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.730942/5867, current 195.742096/5868: elapsed=11168.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.742096
last_received_ts = 195.742081
last_seq = 5868
current_ts = 195.753265
current_received_ts = 195.753159
current_seq = 5869
count = 488
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.742096/5868, current 195.753265/5869: elapsed=11165.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.753265
last_received_ts = 195.753159
last_seq = 5869
current_ts = 195.764435
current_received_ts = 195.764221
current_seq = 5870
count = 489
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.753265/5869, current 195.764435/5870: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.764435
last_received_ts = 195.764221
last_seq = 5870
current_ts = 195.775604
current_received_ts = 195.775436
current_seq = 5871
count = 490
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.764435/5870, current 195.775604/5871: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.775604
last_received_ts = 195.775436
last_seq = 5871
current_ts = 195.786758
current_received_ts = 195.786575
current_seq = 5872
count = 491
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.775604/5871, current 195.786758/5872: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.786758
last_received_ts = 195.786575
last_seq = 5872
current_ts = 195.797928
current_received_ts = 195.797852
current_seq = 5873
count = 492
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.786758/5872, current 195.797928/5873: elapsed=11166.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.797928
last_received_ts = 195.797852
last_seq = 5873
current_ts = 195.809097
current_received_ts = 195.808990
current_seq = 5874
count = 493
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.797928/5873, current 195.809097/5874: elapsed=11167.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.809097
last_received_ts = 195.808990
last_seq = 5874
current_ts = 195.820251
current_received_ts = 195.820145
current_seq = 5875
count = 494
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.809097/5874, current 195.820251/5875: elapsed=11157.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.820251
last_received_ts = 195.820145
last_seq = 5875
current_ts = 195.831421
current_received_ts = 195.831223
current_seq = 5876
count = 495
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.820251/5875, current 195.831421/5876: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.831421
last_received_ts = 195.831223
last_seq = 5876
current_ts = 195.842575
current_received_ts = 195.842422
current_seq = 5877
count = 496
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.831421/5876, current 195.842575/5877: elapsed=11159.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.842575
last_received_ts = 195.842422
last_seq = 5877
current_ts = 195.853729
current_received_ts = 195.853577
current_seq = 5878
count = 497
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.842575/5877, current 195.853729/5878: elapsed=11156.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.853729
last_received_ts = 195.853577
last_seq = 5878
current_ts = 195.864899
current_received_ts = 195.864807
current_seq = 5879
count = 498
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.853729/5878, current 195.864899/5879: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.864899
last_received_ts = 195.864807
last_seq = 5879
current_ts = 195.876053
current_received_ts = 195.875977
current_seq = 5880
count = 499
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.864899/5879, current 195.876053/5880: elapsed=11159.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.876053
last_received_ts = 195.875977
last_seq = 5880
current_ts = 195.887207
current_received_ts = 195.887115
current_seq = 5881
count = 500
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.876053/5880, current 195.887207/5881: elapsed=11160.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.887207
last_received_ts = 195.887115
last_seq = 5881
current_ts = 195.898376
current_received_ts = 195.898224
current_seq = 5882
count = 501
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.887207/5881, current 195.898376/5882: elapsed=11157.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.898376
last_received_ts = 195.898224
last_seq = 5882
current_ts = 195.909531
current_received_ts = 195.909393
current_seq = 5883
count = 502
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.898376/5882, current 195.909531/5883: elapsed=11162.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.909531
last_received_ts = 195.909393
last_seq = 5883
current_ts = 195.920685
current_received_ts = 195.920517
current_seq = 5884
count = 503
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.909531/5883, current 195.920685/5884: elapsed=11160.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.920685
last_received_ts = 195.920517
last_seq = 5884
current_ts = 195.931854
current_received_ts = 195.931747
current_seq = 5885
count = 504
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.920685/5884, current 195.931854/5885: elapsed=11157.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.931854
last_received_ts = 195.931747
last_seq = 5885
current_ts = 195.943008
current_received_ts = 195.942947
current_seq = 5886
count = 505
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.931854/5885, current 195.943008/5886: elapsed=11157.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.943008
last_received_ts = 195.942947
last_seq = 5886
current_ts = 195.954163
current_received_ts = 195.954102
current_seq = 5887
count = 506
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.943008/5886, current 195.954163/5887: elapsed=11163.0us expected=11211.3us +- 56.1us, error 0.4%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.954163
last_received_ts = 195.954102
last_seq = 5887
current_ts = 195.965332
current_received_ts = 195.965164
current_seq = 5888
count = 507
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.954163/5887, current 195.965332/5888: elapsed=11159.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: name = flip
last_ts = 195.965332
last_received_ts = 195.965164
last_seq = 5888
current_ts = 195.976486
current_received_ts = 195.976395
current_seq = 5889
count = 508
seq_step = 1
(kms_flip:2435) DEBUG: flip ts/seq: last 195.965332/5888, current 195.976486/5889: elapsed=11154.0us expected=11211.3us +- 56.1us, error 0.5%
(kms_flip:2435) DEBUG: inconsistent flip ts/seq: last 195.965332/5888, current 195.976486/5889: elapsed=11154.0us expected=11211.3us
(kms_flip:2435) DEBUG: expected 236496, counted 508, encoder type 2
(kms_flip:2435) DEBUG: dropped frames, expected 236496, counted 508, encoder type 2
(kms_flip:2435) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2435) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2435) igt_core-INFO: Stack trace:
(kms_flip:2435) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2435) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2435) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2435) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2435) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2435) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2435) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2435) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (10.164s)
Dmesg
<6> [219.101992] Console: switching to colour dummy device 80x25
<6> [219.102809] [IGT] kms_flip: executing
<7> [219.105289] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [219.106334] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc]
<7> [219.119172] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [219.124011] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1]
<7> [219.124027] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [219.128978] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected
<7> [219.129230] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1]
<7> [219.129238] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [219.133789] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [219.134041] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2]
<7> [219.134049] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [219.134281] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt)
<7> [219.134461] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected
<7> [219.134693] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2]
<7> [219.134700] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [219.134971] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (disconnected -> legacy)
<7> [219.139682] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [219.139930] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3]
<7> [219.139938] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [219.140157] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt)
<7> [219.140334] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected
<7> [219.140569] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4]
<7> [219.140576] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [219.140801] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (disconnected -> tbt-alt)
<7> [219.140964] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected
<7> [219.141266] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1]
<7> [219.141273] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:241:eDP-1]
<7> [219.142192] i915 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [i915]] DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [219.142921] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000
<7> [219.143043] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] sink rates: 162000, 216000, 243000, 270000, 324000, 378000, 432000, 540000
<7> [219.143159] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000
<7> [219.143308] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.
<7> [219.143316] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD monitor
<7> [219.143319] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD size 20, SAD count 0
<7> [219.143340] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] VRR capable: no
<7> [219.143458] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps
<7> [219.144387] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] PCON ENCODER DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [219.144507] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no
<7> [219.145861] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1] probed modes:
<7> [219.145870] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] Probed mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [219.145887] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1]
<7> [219.145894] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [219.150570] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected
<7> [219.150588] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1]
<7> [219.150596] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [219.155578] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [219.155592] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2]
<7> [219.155599] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [219.155811] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected
<7> [219.155825] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2]
<7> [219.155831] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [219.160467] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [219.160481] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3]
<7> [219.160488] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [219.160702] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected
<7> [219.160715] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4]
<7> [219.160721] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [219.160926] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected
<6> [219.161422] [IGT] kms_flip: starting subtest plain-flip-ts-check
<6> [219.163612] [IGT] kms_flip: starting dynamic subtest A-eDP1
<7> [219.163985] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:300]
<7> [219.164032] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:301]
<7> [219.173702] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.174253] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.207272] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.207492] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.224272] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.224495] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.248609] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.248830] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [219.274807] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [219.274896] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [219.275027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [219.275147] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [219.275269] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [219.275422] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0)
<7> [219.275546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [219.275662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [219.275777] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [219.275892] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [219.276006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [219.276120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [219.276233] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [219.276367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [219.276483] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [219.276596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)
<7> [219.276709] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [219.276830] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [219.276950] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [219.277070] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [219.277190] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [219.277325] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [219.277451] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [219.277564] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [219.277677] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [219.277792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [219.277907] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [219.278023] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)
<7> [219.278138] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [219.278325] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [219.278446] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [219.278565] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [219.278679] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [219.278796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [219.278917] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [219.279034] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [219.279153] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)
<7> [219.279283] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [219.279403] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [219.279516] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 540000, found 0)
<7> [219.279632] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [219.279783] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [219.279901] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [219.280038] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0
<7> [219.280155] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [219.280281] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [219.280397] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [219.280508] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [219.280622] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [219.280736] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [219.280857] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [219.280978] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [219.281097] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [219.281217] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [219.281351] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [219.281474] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [219.281595] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [219.281714] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [219.281848] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset]
<7> [219.281971] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [219.282092] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [219.282211] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [219.282347] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [219.282467] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [219.282587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [219.282745] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2
<7> [219.283827] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [219.490492] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0
<7> [219.491331] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [219.495648] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off
<7> [219.496050] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [219.496170] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [219.496520] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short
<7> [219.496672] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [219.547715] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [219.548566] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [219.548605] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [219.548677] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [219.549138] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [219.549303] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [219.549568] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [219.549763] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [219.550071] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [219.550140] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [219.550461] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [219.550809] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [219.551066] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [219.551320] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [219.551586] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [219.551835] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [219.552082] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [219.552331] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [219.552485] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [219.552609] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [219.552799] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [219.552914] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [219.553034] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [219.553162] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [219.553277] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [219.553391] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [219.553528] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [219.553659] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [219.553774] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [219.553905] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [219.554073] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [219.554219] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [219.554392] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [219.554644] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A
<7> [219.554908] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [219.555084] 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> [219.555242] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [219.555528] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [219.555674] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [219.555789] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [219.555907] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [219.555934] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1]
<7> [219.555994] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)
<7> [219.556165] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:82:pipe A] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000
<7> [219.556280] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000
<7> [219.556398] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [219.556538] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:82:pipe A]
<7> [219.556660] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected no, found yes)
<7> [219.556779] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected no, found yes)
<7> [219.556904] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0)
<7> [219.557024] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 0, found 4)
<7> [219.557141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288)
<7> [219.557262] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [219.557382] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [219.557520] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [219.557642] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [219.557760] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [219.557876] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [219.557990] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [219.558104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [219.558223] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [219.558342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [219.558476] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [219.558604] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [219.558730] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [219.558843] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [219.558957] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [219.559069] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [219.559182] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [219.559297] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [219.559427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [219.559549] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [219.559664] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [219.559777] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [219.559892] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [219.560008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [219.560124] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [219.560240] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [219.560359] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [219.560494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [219.560611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [219.560739] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [219.560861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [219.560978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [219.561094] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [219.561209] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 0, found 540000)
<7> [219.561325] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [219.561487] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [219.561614] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1
<7> [219.561763] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001
<7> [219.561882] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95
<7> [219.561998] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [219.562114] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0
<7> [219.562230] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87
<7> [219.562345] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88
<7> [219.562482] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 2055280 num active planes 1
<7> [219.562609] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [219.562734] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [219.562857] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [219.562977] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [219.563096] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [219.563217] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:32:plane 1A] min cdclk (256910 kHz) > [CRTC:82:pipe A] min cdclk (0 kHz)
<7> [219.563346] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz)
<7> [219.563471] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [219.563589] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [219.563709] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [219.563842] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: yes [modeset]
<7> [219.563964] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [219.564087] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 30, dithering: 0
<7> [219.564206] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [219.564327] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [219.564466] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [219.564587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [219.564708] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64
<7> [219.564827] 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> [219.564946] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [219.565065] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [219.565183] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [219.565307] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0
<7> [219.565493] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [219.565614] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14
<7> [219.565733] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [219.565854] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [219.565973] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [219.566090] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [219.566210] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [219.566336] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [219.566458] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [219.566574] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [219.566690] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [219.566806] 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> [219.566920] 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> [219.567037] 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=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [219.567149] 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> [219.567273] 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=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [219.567413] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820
<7> [219.567540] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [219.567659] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [219.567777] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [219.567894] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [219.568012] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000
<7> [219.568131] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [219.568248] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [219.568374] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [219.568495] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.568615] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.568728] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.568841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [219.568954] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [219.569071] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.569187] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.569310] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [219.569430] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [219.569544] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [FB:300] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [219.569658] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [219.569771] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [219.569884] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [219.569996] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [219.570108] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [219.570222] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [219.570347] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [219.573334] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [219.573486] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [219.573611] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<7> [219.573788] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [219.573945] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [219.574376] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_A
<7> [219.574604] 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> [219.574822] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [219.574965] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [219.575112] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [219.575262] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [219.575403] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [219.575539] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [219.575674] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [219.575807] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [219.575943] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [219.576067] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [219.576181] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [219.576327] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [219.576447] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [219.576560] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [219.576686] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [219.576802] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [219.576920] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [219.577031] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [219.577142] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [219.577276] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [219.577393] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [219.577528] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [219.577659] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [219.577772] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf
<7> [219.578000] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *)
<7> [219.578126] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)
<7> [219.578309] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [219.579203] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on
<7> [219.579350] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (469 ms remaining)
<7> [220.052947] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060
<7> [220.069763] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [220.070305] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on
<7> [220.070778] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [220.102513] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [220.102982] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [220.103409] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [220.103943] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [220.171638] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (tbt-alt -> disconnected)
<7> [220.171752] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected)
<7> [220.171907] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (legacy -> disconnected)
<7> [220.171914] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected)
<7> [220.271640] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [220.274156] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [220.274627] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [220.278502] 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> [220.279347] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [220.280438] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07
<7> [220.281420] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [220.282092] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [220.283292] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK
<7> [220.283410] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [220.284886] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [220.285002] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4
<7> [220.285628] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A
<7> [220.285888] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [220.286005] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe A
<7> [220.286176] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892
<7> [220.297278] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2
<7> [220.298853] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [220.299035] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [222.840148] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off
<7> [222.840687] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [226.170694] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [226.171193] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [226.171762] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [229.328273] [IGT] kms_flip: finished subtest A-eDP1, FAIL
Created at 2025-03-21 16:14:55