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

Machine description: shard-mtlp-1

Result: Fail

git-log-oneline i915_display_info5 igt_runner5 runtimes5 results5.json results5-i915-load.json i915_display_info_post_exec5 boot5 dmesg5

DetailValue
Duration 12.25 seconds
Hostname 
shard-mtlp-1
Igt-Version 
IGT-Version: 1.30-g0a4beb5fb (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16231-g3ccfd8016ad8+ x86_64)
Out 
Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11174.4us +- 2.250us accuracy 0.06%
vblank interval differs from modeline! expected 11111.1us, measured 11174us +- 2.250us, difference 63.3us (28.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (12.249s)
Err 
Starting dynamic subtest: B-eDP1
(kms_flip:2213) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2213) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.010925
last_received_ts = 72.010612
last_seq = 572
current_ts = 72.022064
current_received_ts = 72.021751
current_seq = 573
count = 552
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.010925/572, current 72.022064/573: elapsed=11141.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.022064
last_received_ts = 72.021751
last_seq = 573
current_ts = 72.033211
current_received_ts = 72.032875
current_seq = 574
count = 553
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.022064/573, current 72.033211/574: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.033211
last_received_ts = 72.032875
last_seq = 574
current_ts = 72.044350
current_received_ts = 72.044067
current_seq = 575
count = 554
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.033211/574, current 72.044350/575: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.044350
last_received_ts = 72.044067
last_seq = 575
current_ts = 72.055481
current_received_ts = 72.055199
current_seq = 576
count = 555
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.044350/575, current 72.055481/576: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.055481
last_received_ts = 72.055199
last_seq = 576
current_ts = 72.066612
current_received_ts = 72.066307
current_seq = 577
count = 556
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.055481/576, current 72.066612/577: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.066612
last_received_ts = 72.066307
last_seq = 577
current_ts = 72.077759
current_received_ts = 72.077469
current_seq = 578
count = 557
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.066612/577, current 72.077759/578: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.077759
last_received_ts = 72.077469
last_seq = 578
current_ts = 72.088890
current_received_ts = 72.088593
current_seq = 579
count = 558
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.077759/578, current 72.088890/579: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.088890
last_received_ts = 72.088593
last_seq = 579
current_ts = 72.100029
current_received_ts = 72.099701
current_seq = 580
count = 559
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.088890/579, current 72.100029/580: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.100029
last_received_ts = 72.099701
last_seq = 580
current_ts = 72.111160
current_received_ts = 72.110855
current_seq = 581
count = 560
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.100029/580, current 72.111160/581: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.111160
last_received_ts = 72.110855
last_seq = 581
current_ts = 72.122299
current_received_ts = 72.121986
current_seq = 582
count = 561
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.111160/581, current 72.122299/582: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.122299
last_received_ts = 72.121986
last_seq = 582
current_ts = 72.133438
current_received_ts = 72.133102
current_seq = 583
count = 562
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.122299/582, current 72.133438/583: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.133438
last_received_ts = 72.133102
last_seq = 583
current_ts = 72.144569
current_received_ts = 72.144264
current_seq = 584
count = 563
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.133438/583, current 72.144569/584: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.144569
last_received_ts = 72.144264
last_seq = 584
current_ts = 72.155701
current_received_ts = 72.155388
current_seq = 585
count = 564
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.144569/584, current 72.155701/585: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.155701
last_received_ts = 72.155388
last_seq = 585
current_ts = 72.166840
current_received_ts = 72.166550
current_seq = 586
count = 565
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.155701/585, current 72.166840/586: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.166840
last_received_ts = 72.166550
last_seq = 586
current_ts = 72.177979
current_received_ts = 72.177689
current_seq = 587
count = 566
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.166840/586, current 72.177979/587: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.177979
last_received_ts = 72.177689
last_seq = 587
current_ts = 72.189117
current_received_ts = 72.188789
current_seq = 588
count = 567
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.177979/587, current 72.189117/588: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.189117
last_received_ts = 72.188789
last_seq = 588
current_ts = 72.200249
current_received_ts = 72.199936
current_seq = 589
count = 568
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.189117/588, current 72.200249/589: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.200249
last_received_ts = 72.199936
last_seq = 589
current_ts = 72.211388
current_received_ts = 72.211090
current_seq = 590
count = 569
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.200249/589, current 72.211388/590: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.211388
last_received_ts = 72.211090
last_seq = 590
current_ts = 72.222519
current_received_ts = 72.222206
current_seq = 591
count = 570
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.211388/590, current 72.222519/591: elapsed=11131.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.222519
last_received_ts = 72.222206
last_seq = 591
current_ts = 72.233658
current_received_ts = 72.233345
current_seq = 592
count = 571
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.222519/591, current 72.233658/592: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.233658
last_received_ts = 72.233345
last_seq = 592
current_ts = 72.244797
current_received_ts = 72.244476
current_seq = 593
count = 572
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.233658/592, current 72.244797/593: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.244797
last_received_ts = 72.244476
last_seq = 593
current_ts = 72.255928
current_received_ts = 72.255638
current_seq = 594
count = 573
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.244797/593, current 72.255928/594: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.255928
last_received_ts = 72.255638
last_seq = 594
current_ts = 72.267067
current_received_ts = 72.266762
current_seq = 595
count = 574
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.255928/594, current 72.267067/595: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.267067
last_received_ts = 72.266762
last_seq = 595
current_ts = 72.278198
current_received_ts = 72.277908
current_seq = 596
count = 575
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.267067/595, current 72.278198/596: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.278198
last_received_ts = 72.277908
last_seq = 596
current_ts = 72.289337
current_received_ts = 72.289062
current_seq = 597
count = 576
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.278198/596, current 72.289337/597: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.289337
last_received_ts = 72.289062
last_seq = 597
current_ts = 72.300476
current_received_ts = 72.300201
current_seq = 598
count = 577
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.289337/597, current 72.300476/598: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.300476
last_received_ts = 72.300201
last_seq = 598
current_ts = 72.311607
current_received_ts = 72.311302
current_seq = 599
count = 578
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.300476/598, current 72.311607/599: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.311607
last_received_ts = 72.311302
last_seq = 599
current_ts = 72.322746
current_received_ts = 72.322418
current_seq = 600
count = 579
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.311607/599, current 72.322746/600: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.322746
last_received_ts = 72.322418
last_seq = 600
current_ts = 72.333878
current_received_ts = 72.333588
current_seq = 601
count = 580
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.322746/600, current 72.333878/601: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.333878
last_received_ts = 72.333588
last_seq = 601
current_ts = 72.345016
current_received_ts = 72.344719
current_seq = 602
count = 581
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.333878/601, current 72.345016/602: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.345016
last_received_ts = 72.344719
last_seq = 602
current_ts = 72.356155
current_received_ts = 72.355858
current_seq = 603
count = 582
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.345016/602, current 72.356155/603: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.356155
last_received_ts = 72.355858
last_seq = 603
current_ts = 72.367287
current_received_ts = 72.367058
current_seq = 604
count = 583
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.356155/603, current 72.367287/604: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.367287
last_received_ts = 72.367058
last_seq = 604
current_ts = 72.378426
current_received_ts = 72.378143
current_seq = 605
count = 584
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.367287/604, current 72.378426/605: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.378426
last_received_ts = 72.378143
last_seq = 605
current_ts = 72.389557
current_received_ts = 72.389252
current_seq = 606
count = 585
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.378426/605, current 72.389557/606: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.389557
last_received_ts = 72.389252
last_seq = 606
current_ts = 72.400696
current_received_ts = 72.400391
current_seq = 607
count = 586
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.389557/606, current 72.400696/607: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.400696
last_received_ts = 72.400391
last_seq = 607
current_ts = 72.411835
current_received_ts = 72.411545
current_seq = 608
count = 587
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.400696/607, current 72.411835/608: elapsed=11141.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.411835
last_received_ts = 72.411545
last_seq = 608
current_ts = 72.422966
current_received_ts = 72.422661
current_seq = 609
count = 588
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.411835/608, current 72.422966/609: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.422966
last_received_ts = 72.422661
last_seq = 609
current_ts = 72.434105
current_received_ts = 72.433823
current_seq = 610
count = 589
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.422966/609, current 72.434105/610: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.434105
last_received_ts = 72.433823
last_seq = 610
current_ts = 72.445244
current_received_ts = 72.444931
current_seq = 611
count = 590
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.434105/610, current 72.445244/611: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.445244
last_received_ts = 72.444931
last_seq = 611
current_ts = 72.456375
current_received_ts = 72.456078
current_seq = 612
count = 591
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.445244/611, current 72.456375/612: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.456375
last_received_ts = 72.456078
last_seq = 612
current_ts = 72.467514
current_received_ts = 72.467209
current_seq = 613
count = 592
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.456375/612, current 72.467514/613: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.467514
last_received_ts = 72.467209
last_seq = 613
current_ts = 72.478653
current_received_ts = 72.478363
current_seq = 614
count = 593
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.467514/613, current 72.478653/614: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.478653
last_received_ts = 72.478363
last_seq = 614
current_ts = 72.489784
current_received_ts = 72.489487
current_seq = 615
count = 594
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.478653/614, current 72.489784/615: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.489784
last_received_ts = 72.489487
last_seq = 615
current_ts = 72.500923
current_received_ts = 72.500671
current_seq = 616
count = 595
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.489784/615, current 72.500923/616: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.500923
last_received_ts = 72.500671
last_seq = 616
current_ts = 72.512054
current_received_ts = 72.511749
current_seq = 617
count = 596
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.500923/616, current 72.512054/617: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.512054
last_received_ts = 72.511749
last_seq = 617
current_ts = 72.523193
current_received_ts = 72.522942
current_seq = 618
count = 597
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.512054/617, current 72.523193/618: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.523193
last_received_ts = 72.522942
last_seq = 618
current_ts = 72.534325
current_received_ts = 72.534042
current_seq = 619
count = 598
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.523193/618, current 72.534325/619: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.534325
last_received_ts = 72.534042
last_seq = 619
current_ts = 72.545464
current_received_ts = 72.545158
current_seq = 620
count = 599
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.534325/619, current 72.545464/620: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.545464
last_received_ts = 72.545158
last_seq = 620
current_ts = 72.556602
current_received_ts = 72.556297
current_seq = 621
count = 600
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.545464/620, current 72.556602/621: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.556602
last_received_ts = 72.556297
last_seq = 621
current_ts = 72.567741
current_received_ts = 72.567436
current_seq = 622
count = 601
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.556602/621, current 72.567741/622: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.567741
last_received_ts = 72.567436
last_seq = 622
current_ts = 72.578873
current_received_ts = 72.578568
current_seq = 623
count = 602
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.567741/622, current 72.578873/623: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.578873
last_received_ts = 72.578568
last_seq = 623
current_ts = 72.590012
current_received_ts = 72.589722
current_seq = 624
count = 603
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.578873/623, current 72.590012/624: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.590012
last_received_ts = 72.589722
last_seq = 624
current_ts = 72.601143
current_received_ts = 72.600838
current_seq = 625
count = 604
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.590012/624, current 72.601143/625: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.601143
last_received_ts = 72.600838
last_seq = 625
current_ts = 72.612282
current_received_ts = 72.611984
current_seq = 626
count = 605
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.601143/625, current 72.612282/626: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.612282
last_received_ts = 72.611984
last_seq = 626
current_ts = 72.623421
current_received_ts = 72.623123
current_seq = 627
count = 606
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.612282/626, current 72.623421/627: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.623421
last_received_ts = 72.623123
last_seq = 627
current_ts = 72.634552
current_received_ts = 72.634247
current_seq = 628
count = 607
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.623421/627, current 72.634552/628: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.634552
last_received_ts = 72.634247
last_seq = 628
current_ts = 72.645683
current_received_ts = 72.645386
current_seq = 629
count = 608
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.634552/628, current 72.645683/629: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.645683
last_received_ts = 72.645386
last_seq = 629
current_ts = 72.656822
current_received_ts = 72.656540
current_seq = 630
count = 609
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.645683/629, current 72.656822/630: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.656822
last_received_ts = 72.656540
last_seq = 630
current_ts = 72.667961
current_received_ts = 72.667648
current_seq = 631
count = 610
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.656822/630, current 72.667961/631: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.667961
last_received_ts = 72.667648
last_seq = 631
current_ts = 72.679100
current_received_ts = 72.678787
current_seq = 632
count = 611
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.667961/631, current 72.679100/632: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.679100
last_received_ts = 72.678787
last_seq = 632
current_ts = 72.690239
current_received_ts = 72.689934
current_seq = 633
count = 612
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.679100/632, current 72.690239/633: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.690239
last_received_ts = 72.689934
last_seq = 633
current_ts = 72.701370
current_received_ts = 72.701057
current_seq = 634
count = 613
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.690239/633, current 72.701370/634: elapsed=11131.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.701370
last_received_ts = 72.701057
last_seq = 634
current_ts = 72.712509
current_received_ts = 72.712204
current_seq = 635
count = 614
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.701370/634, current 72.712509/635: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.712509
last_received_ts = 72.712204
last_seq = 635
current_ts = 72.723640
current_received_ts = 72.723328
current_seq = 636
count = 615
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.712509/635, current 72.723640/636: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.723640
last_received_ts = 72.723328
last_seq = 636
current_ts = 72.734779
current_received_ts = 72.734520
current_seq = 637
count = 616
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.723640/636, current 72.734779/637: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.734779
last_received_ts = 72.734520
last_seq = 637
current_ts = 72.745911
current_received_ts = 72.745636
current_seq = 638
count = 617
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.734779/637, current 72.745911/638: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.745911
last_received_ts = 72.745636
last_seq = 638
current_ts = 72.757050
current_received_ts = 72.756767
current_seq = 639
count = 618
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.745911/638, current 72.757050/639: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.757050
last_received_ts = 72.756767
last_seq = 639
current_ts = 72.768188
current_received_ts = 72.767883
current_seq = 640
count = 619
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.757050/639, current 72.768188/640: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.768188
last_received_ts = 72.767883
last_seq = 640
current_ts = 72.779327
current_received_ts = 72.779022
current_seq = 641
count = 620
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.768188/640, current 72.779327/641: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.779327
last_received_ts = 72.779022
last_seq = 641
current_ts = 72.790459
current_received_ts = 72.790154
current_seq = 642
count = 621
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.779327/641, current 72.790459/642: elapsed=11131.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.790459
last_received_ts = 72.790154
last_seq = 642
current_ts = 72.801590
current_received_ts = 72.801292
current_seq = 643
count = 622
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.790459/642, current 72.801590/643: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.801590
last_received_ts = 72.801292
last_seq = 643
current_ts = 72.812729
current_received_ts = 72.812447
current_seq = 644
count = 623
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.801590/643, current 72.812729/644: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.812729
last_received_ts = 72.812447
last_seq = 644
current_ts = 72.823868
current_received_ts = 72.823563
current_seq = 645
count = 624
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.812729/644, current 72.823868/645: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.823868
last_received_ts = 72.823563
last_seq = 645
current_ts = 72.835007
current_received_ts = 72.834686
current_seq = 646
count = 625
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.823868/645, current 72.835007/646: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.835007
last_received_ts = 72.834686
last_seq = 646
current_ts = 72.846138
current_received_ts = 72.845840
current_seq = 647
count = 626
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.835007/646, current 72.846138/647: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.846138
last_received_ts = 72.845840
last_seq = 647
current_ts = 72.857277
current_received_ts = 72.856956
current_seq = 648
count = 627
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.846138/647, current 72.857277/648: elapsed=11139.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.857277
last_received_ts = 72.856956
last_seq = 648
current_ts = 72.868408
current_received_ts = 72.868080
current_seq = 649
count = 628
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.857277/648, current 72.868408/649: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.868408
last_received_ts = 72.868080
last_seq = 649
current_ts = 72.879547
current_received_ts = 72.879234
current_seq = 650
count = 629
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.868408/649, current 72.879547/650: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.879547
last_received_ts = 72.879234
last_seq = 650
current_ts = 72.890678
current_received_ts = 72.890366
current_seq = 651
count = 630
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.879547/650, current 72.890678/651: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.890678
last_received_ts = 72.890366
last_seq = 651
current_ts = 72.901817
current_received_ts = 72.901497
current_seq = 652
count = 631
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.890678/651, current 72.901817/652: elapsed=11140.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.901817
last_received_ts = 72.901497
last_seq = 652
current_ts = 72.912956
current_received_ts = 72.912666
current_seq = 653
count = 632
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.901817/652, current 72.912956/653: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.912956
last_received_ts = 72.912666
last_seq = 653
current_ts = 72.924088
current_received_ts = 72.923767
current_seq = 654
count = 633
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.912956/653, current 72.924088/654: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.924088
last_received_ts = 72.923767
last_seq = 654
current_ts = 72.935226
current_received_ts = 72.934937
current_seq = 655
count = 634
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.924088/654, current 72.935226/655: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.935226
last_received_ts = 72.934937
last_seq = 655
current_ts = 72.946365
current_received_ts = 72.946068
current_seq = 656
count = 635
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.935226/655, current 72.946365/656: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.946365
last_received_ts = 72.946068
last_seq = 656
current_ts = 72.957497
current_received_ts = 72.957207
current_seq = 657
count = 636
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.946365/656, current 72.957497/657: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.957497
last_received_ts = 72.957207
last_seq = 657
current_ts = 72.968636
current_received_ts = 72.968315
current_seq = 658
count = 637
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.957497/657, current 72.968636/658: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.968636
last_received_ts = 72.968315
last_seq = 658
current_ts = 72.979767
current_received_ts = 72.979462
current_seq = 659
count = 638
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.968636/658, current 72.979767/659: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.979767
last_received_ts = 72.979462
last_seq = 659
current_ts = 72.990906
current_received_ts = 72.990585
current_seq = 660
count = 639
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.979767/659, current 72.990906/660: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 72.990906
last_received_ts = 72.990585
last_seq = 660
current_ts = 73.002037
current_received_ts = 73.001778
current_seq = 661
count = 640
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 72.990906/660, current 73.002037/661: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.002037
last_received_ts = 73.001778
last_seq = 661
current_ts = 73.013184
current_received_ts = 73.012901
current_seq = 662
count = 641
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.002037/661, current 73.013184/662: elapsed=11141.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.013184
last_received_ts = 73.012901
last_seq = 662
current_ts = 73.024315
current_received_ts = 73.023987
current_seq = 663
count = 642
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.013184/662, current 73.024315/663: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.024315
last_received_ts = 73.023987
last_seq = 663
current_ts = 73.035454
current_received_ts = 73.035172
current_seq = 664
count = 643
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.024315/663, current 73.035454/664: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.035454
last_received_ts = 73.035172
last_seq = 664
current_ts = 73.046585
current_received_ts = 73.046280
current_seq = 665
count = 644
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.035454/664, current 73.046585/665: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.046585
last_received_ts = 73.046280
last_seq = 665
current_ts = 73.057716
current_received_ts = 73.057396
current_seq = 666
count = 645
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.046585/665, current 73.057716/666: elapsed=11130.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.057716
last_received_ts = 73.057396
last_seq = 666
current_ts = 73.068848
current_received_ts = 73.068550
current_seq = 667
count = 646
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.057716/666, current 73.068848/667: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.068848
last_received_ts = 73.068550
last_seq = 667
current_ts = 73.079979
current_received_ts = 73.079697
current_seq = 668
count = 647
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.068848/667, current 73.079979/668: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.079979
last_received_ts = 73.079697
last_seq = 668
current_ts = 73.091110
current_received_ts = 73.090797
current_seq = 669
count = 648
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.079979/668, current 73.091110/669: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.091110
last_received_ts = 73.090797
last_seq = 669
current_ts = 73.102249
current_received_ts = 73.101982
current_seq = 670
count = 649
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.091110/669, current 73.102249/670: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.102249
last_received_ts = 73.101982
last_seq = 670
current_ts = 73.113380
current_received_ts = 73.113075
current_seq = 671
count = 650
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.102249/670, current 73.113380/671: elapsed=11138.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.113380
last_received_ts = 73.113075
last_seq = 671
current_ts = 73.124512
current_received_ts = 73.124191
current_seq = 672
count = 651
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.113380/671, current 73.124512/672: elapsed=11130.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.124512
last_received_ts = 73.124191
last_seq = 672
current_ts = 73.135651
current_received_ts = 73.135368
current_seq = 673
count = 652
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.124512/672, current 73.135651/673: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.135651
last_received_ts = 73.135368
last_seq = 673
current_ts = 73.146782
current_received_ts = 73.146500
current_seq = 674
count = 653
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.135651/673, current 73.146782/674: elapsed=11135.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.146782
last_received_ts = 73.146500
last_seq = 674
current_ts = 73.157913
current_received_ts = 73.157608
current_seq = 675
count = 654
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.146782/674, current 73.157913/675: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.157913
last_received_ts = 73.157608
last_seq = 675
current_ts = 73.169044
current_received_ts = 73.168747
current_seq = 676
count = 655
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.157913/675, current 73.169044/676: elapsed=11130.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.169044
last_received_ts = 73.168747
last_seq = 676
current_ts = 73.180176
current_received_ts = 73.179871
current_seq = 677
count = 656
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.169044/676, current 73.180176/677: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.180176
last_received_ts = 73.179871
last_seq = 677
current_ts = 73.191315
current_received_ts = 73.190994
current_seq = 678
count = 657
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.180176/677, current 73.191315/678: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.191315
last_received_ts = 73.190994
last_seq = 678
current_ts = 73.202446
current_received_ts = 73.202179
current_seq = 679
count = 658
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.191315/678, current 73.202446/679: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.202446
last_received_ts = 73.202179
last_seq = 679
current_ts = 73.213577
current_received_ts = 73.213272
current_seq = 680
count = 659
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.202446/679, current 73.213577/680: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.213577
last_received_ts = 73.213272
last_seq = 680
current_ts = 73.224709
current_received_ts = 73.224403
current_seq = 681
count = 660
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.213577/680, current 73.224709/681: elapsed=11129.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.224709
last_received_ts = 73.224403
last_seq = 681
current_ts = 73.235840
current_received_ts = 73.235542
current_seq = 682
count = 661
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.224709/681, current 73.235840/682: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.235840
last_received_ts = 73.235542
last_seq = 682
current_ts = 73.246979
current_received_ts = 73.246666
current_seq = 683
count = 662
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.235840/682, current 73.246979/683: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.246979
last_received_ts = 73.246666
last_seq = 683
current_ts = 73.258110
current_received_ts = 73.257805
current_seq = 684
count = 663
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.246979/683, current 73.258110/684: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.258110
last_received_ts = 73.257805
last_seq = 684
current_ts = 73.269241
current_received_ts = 73.268951
current_seq = 685
count = 664
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.258110/684, current 73.269241/685: elapsed=11129.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.269241
last_received_ts = 73.268951
last_seq = 685
current_ts = 73.280373
current_received_ts = 73.280067
current_seq = 686
count = 665
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.269241/685, current 73.280373/686: elapsed=11134.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.280373
last_received_ts = 73.280067
last_seq = 686
current_ts = 73.291504
current_received_ts = 73.291206
current_seq = 687
count = 666
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.280373/686, current 73.291504/687: elapsed=11131.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.291504
last_received_ts = 73.291206
last_seq = 687
current_ts = 73.302643
current_received_ts = 73.302330
current_seq = 688
count = 667
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.291504/687, current 73.302643/688: elapsed=11136.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.302643
last_received_ts = 73.302330
last_seq = 688
current_ts = 73.313774
current_received_ts = 73.313477
current_seq = 689
count = 668
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.302643/688, current 73.313774/689: elapsed=11130.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.313774
last_received_ts = 73.313477
last_seq = 689
current_ts = 73.324905
current_received_ts = 73.324654
current_seq = 690
count = 669
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.313774/689, current 73.324905/690: elapsed=11137.0us expected=11174.4us +- 55.9us, error 0.3%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.324905
last_received_ts = 73.324654
last_seq = 690
current_ts = 73.336044
current_received_ts = 73.335732
current_seq = 691
count = 670
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.324905/690, current 73.336044/691: elapsed=11132.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.336044
last_received_ts = 73.335732
last_seq = 691
current_ts = 73.347176
current_received_ts = 73.346863
current_seq = 692
count = 671
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.336044/691, current 73.347176/692: elapsed=11133.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: name = flip
last_ts = 73.347176
last_received_ts = 73.346863
last_seq = 692
current_ts = 73.358307
current_received_ts = 73.358070
current_seq = 693
count = 672
seq_step = 1
(kms_flip:2213) DEBUG: flip ts/seq: last 73.347176/692, current 73.358307/693: elapsed=11131.0us expected=11174.4us +- 55.9us, error 0.4%
(kms_flip:2213) DEBUG: expected 671, counted 673, encoder type 2
(kms_flip:2213) DEBUG: dropped frames, expected 671, counted 673, encoder type 2
(kms_flip:2213) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2213) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2213) igt_core-INFO: Stack trace:
(kms_flip:2213) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2213) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2213) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2213) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2213) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2213) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2213) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2213) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (12.249s)
Dmesg
<6> [64.256489] [IGT] kms_flip: starting dynamic subtest B-eDP1
<7> [64.257241] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:242]
<7> [64.257318] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:303]
<7> [64.269856] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.270614] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.296598] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.296819] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.319567] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.319764] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.344881] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.345188] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [64.373941] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [64.374024] 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> [64.374149] 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> [64.374265] 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> [64.374380] 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> [64.374493] 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> [64.374606] 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> [64.374721] 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> [64.374834] 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> [64.374983] 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> [64.375097] 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> [64.375209] 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> [64.375320] 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> [64.375432] 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> [64.375544] 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> [64.375656] 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> [64.375767] 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> [64.375899] 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> [64.376015] 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> [64.376127] 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> [64.376239] 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> [64.376350] 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> [64.376461] 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> [64.376572] 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> [64.376682] 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> [64.376792] 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> [64.376915] 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> [64.377027] 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> [64.377138] 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> [64.377248] 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> [64.377358] 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> [64.377468] 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> [64.377579] 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> [64.377689] 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> [64.377800] 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> [64.377921] 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> [64.378038] 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> [64.378149] 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> [64.378260] 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> [64.378372] 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> [64.378483] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [64.378627] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [64.378737] 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> [64.378881] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0
<7> [64.378992] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [64.379099] 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> [64.379206] 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> [64.379314] 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> [64.379422] 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> [64.379531] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [64.379649] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [64.379763] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [64.379910] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [64.380022] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [64.380134] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [64.380247] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [64.380357] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [64.380466] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [64.380593] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset]
<7> [64.380709] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [64.380822] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [64.380955] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [64.381070] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [64.381183] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [64.381295] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [64.381448] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [64.382175] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [64.382844] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2
<7> [64.383218] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [64.383449] 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: 0x0000006f
<7> [64.384665] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [64.587646] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0
<7> [64.588310] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [64.596710] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off
<7> [64.597086] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [64.597147] 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> [64.597560] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short
<7> [64.597661] 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> [64.647549] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [64.648073] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [64.648637] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [64.648923] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [64.649066] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [64.649499] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [64.649702] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [64.649874] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [64.650163] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [64.650283] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [64.650616] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [64.650593] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [64.650814] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [64.651016] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [64.651107] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [64.651239] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [64.651439] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [64.651634] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [64.651820] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [64.652179] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [64.652520] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [64.652811] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [64.653042] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [64.653232] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [64.653409] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [64.653568] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [64.653723] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [64.653863] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [64.653987] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [64.654108] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [64.654248] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [64.654381] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [64.654499] 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> [64.654677] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [64.654822] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [64.655069] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A
<7> [64.655285] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [64.655662] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [64.655816] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [64.655911] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [64.656013] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [64.656043] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1]
<7> [64.656095] 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> [64.656227] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:134:pipe B] 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> [64.656334] 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> [64.656445] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:134:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [64.656558] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:134:pipe B]
<7> [64.656664] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [64.656777] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [64.656890] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [64.657002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in lane_count (expected 0, found 4)
<7> [64.657131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] 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> [64.657242] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [64.657350] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [64.657459] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [64.657570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [64.657678] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [64.657788] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [64.657898] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [64.658006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [64.658131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [64.658242] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [64.658353] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [64.658461] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [64.658568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [64.658676] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [64.658785] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [64.658893] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [64.659000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [64.659122] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [64.659236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [64.659345] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [64.659453] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [64.659562] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [64.659671] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [64.659780] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [64.659889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [64.659996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [64.660119] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [64.660229] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [64.660339] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [64.660447] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [64.660554] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in dpll_hw_state.cx0pll C20
<7> [64.660660] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [64.660766] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] c20pll_hw_state:
<7> [64.660871] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] tx[0] = 0x0000, tx[1] = 0x0000, tx[2] = 0x0000
<7> [64.660978] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] cmn[0] = 0x0000, cmn[1] = 0x0000, cmn[2] = 0x0000, cmn[3] = 0x0000
<7> [64.661097] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[0] = 0x0000
<7> [64.661204] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[1] = 0x0000
<7> [64.661307] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[2] = 0x0000
<7> [64.661410] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[3] = 0x0000
<7> [64.661514] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[4] = 0x0000
<7> [64.661615] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[5] = 0x0000
<7> [64.661719] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[6] = 0x0000
<7> [64.661823] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[7] = 0x0000
<7> [64.661927] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[8] = 0x0000
<7> [64.662038] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] mplla[9] = 0x0000
<7> [64.662149] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [64.662260] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] c10pll_hw_state: fracen: yes,
<7> [64.662363] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] quot: 40960, rem: 0, den: 1,
<7> [64.662467] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] multiplier: 140, tx_clk_div: 0.
<7> [64.662572] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] c10pll_rawhw_state:
<7> [64.662677] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] tx: 0x10, cmn: 0x21
<7> [64.662782] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] pll[0] = 0xf4, pll[1] = 0x0, pll[2] = 0xf8, pll[3] = 0x0
<7> [64.662887] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0
<7> [64.662998] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0
<7> [64.663107] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] pll[12] = 0xa0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x0
<7> [64.663212] i915 0000:00:02.0: [drm:intel_cx0pll_dump_hw_state [i915]] pll[16] = 0x84, pll[17] = 0x4f, pll[18] = 0xe5, pll[19] = 0x23
<7> [64.663317] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [64.663431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [64.663546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [64.663658] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in port_clock (expected 0, found 540000)
<7> [64.663769] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:134:pipe B] fastset requirement not met, forcing full modeset
<7> [64.663905] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [64.664028] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:134:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2
<7> [64.664159] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001
<7> [64.664269] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:129:cursor B] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95
<7> [64.664375] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [64.664481] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0
<7> [64.664588] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87
<7> [64.664694] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] 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> [64.664802] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:134:pipe B] data rate 2055280 num active planes 1
<7> [64.664920] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [64.665043] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [64.665159] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [64.665271] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [64.665382] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [64.665491] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:84:plane 1B] min cdclk (256910 kHz) > [CRTC:134:pipe B] min cdclk (0 kHz)
<7> [64.665602] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz)
<7> [64.665714] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [64.665822] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [64.665930] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [64.666057] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:134:pipe B] enable: yes [modeset]
<7> [64.666171] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [64.666283] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 30, dithering: 0
<7> [64.666393] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [64.666504] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [64.666615] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [64.666727] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [64.666838] 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> [64.666952] 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> [64.667078] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [64.667190] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [64.667300] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [64.667408] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0
<7> [64.667517] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [64.667626] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14
<7> [64.667733] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [64.667841] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [64.667949] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [64.668070] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [64.668178] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [64.668288] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [64.668397] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [64.668505] 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> [64.668614] 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> [64.668722] 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> [64.668832] 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> [64.668940] 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> [64.669062] 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> [64.669171] 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> [64.669278] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820
<7> [64.669386] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [64.669494] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [64.669602] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [64.669710] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [64.669818] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000
<7> [64.669926] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [64.670079] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [64.670191] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [64.670299] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.670407] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.670515] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.670622] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [64.670729] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [64.670837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.670950] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.671061] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [64.671170] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [64.671276] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:84:plane 1B] fb: [FB:242] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [64.671383] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [64.671490] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [64.671598] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 2B] fb: [NOFB], visible: no
<7> [64.671703] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:102:plane 3B] fb: [NOFB], visible: no
<7> [64.671810] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:111:plane 4B] fb: [NOFB], visible: no
<7> [64.671916] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:120:plane 5B] fb: [NOFB], visible: no
<7> [64.672037] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:129:cursor B] fb: [NOFB], visible: no
<7> [64.672975] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [64.673621] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [64.674102] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<7> [64.674576] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [64.674706] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [64.675143] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [64.675375] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_B
<7> [64.675568] 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> [64.675728] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [64.675842] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [64.675966] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [64.676077] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [64.676184] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [64.676291] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [64.676399] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [64.676504] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [64.676611] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [64.676719] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [64.676826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [64.676940] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [64.677048] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [64.677156] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [64.677264] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [64.677370] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [64.677476] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [64.677582] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [64.677689] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [64.677796] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [64.677918] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [64.678030] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [64.678143] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [64.678251] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf
<7> [64.678465] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *)
<7> [64.678586] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)
<7> [64.678740] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [64.680082] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on
<7> [64.680225] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining)
<7> [65.152704] 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> [65.221498] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [65.222065] 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> [65.222559] 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> [65.254135] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [65.254605] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [65.255039] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [65.255521] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [65.424753] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [65.427138] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [65.427539] 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> [65.431425] 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> [65.432270] 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> [65.433137] 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> [65.434086] 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> [65.434739] 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> [65.435861] 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> [65.435970] 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> [65.437477] 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> [65.437581] 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> [65.438146] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [65.438356] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [65.438480] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe B
<7> [65.438650] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892
<7> [65.449598] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2
<7> [65.451088] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [65.451257] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:134:pipe B]
<7> [67.946515] 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> [67.947058] 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> [73.145536] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [73.146046] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [73.146504] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [76.506113] [IGT] kms_flip: finished subtest B-eDP1, FAIL
Created at 2025-03-06 07:35:37