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

Machine description: shard-snb4

Result: Fail

git-log-oneline i915_display_info23 igt_runner23 runtimes23 results23.json results23-i915-load.json i915_display_info_post_exec23 boot23 dmesg23

DetailValue
Duration 6.40 seconds
Hostname 
shard-snb4
Igt-Version 
IGT-Version: 2.0-g0498a2e21 (x86_64) (Linux: 6.14.0-rc6-CI_DRM_16293-ga958e31a81b3+ x86_64)
Out 
Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Expected frametime: 16666us; measured 16964.9us +- 2.527us accuracy 0.04%
vblank interval differs from modeline! expected 16665.6us, measured 16965us +- 2.527us, difference 299.3us (118.5 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 B-VGA1: FAIL (6.401s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:2656) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2656) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:2656) DEBUG: flip ts/seq: last 151.976318/764, current 151.993256/765: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 151.993256
last_received_ts = 151.992691
last_seq = 765
current_ts = 152.010193
current_received_ts = 152.009628
current_seq = 766
count = 48
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 151.993256/765, current 152.010193/766: elapsed=16935.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.010193
last_received_ts = 152.009628
last_seq = 766
current_ts = 152.027130
current_received_ts = 152.026566
current_seq = 767
count = 49
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.010193/766, current 152.027130/767: elapsed=16935.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.027130
last_received_ts = 152.026566
last_seq = 767
current_ts = 152.044067
current_received_ts = 152.043488
current_seq = 768
count = 50
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.027130/767, current 152.044067/768: elapsed=16935.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.044067
last_received_ts = 152.043488
last_seq = 768
current_ts = 152.060989
current_received_ts = 152.060440
current_seq = 769
count = 51
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.044067/768, current 152.060989/769: elapsed=16935.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.060989
last_received_ts = 152.060440
last_seq = 769
current_ts = 152.077927
current_received_ts = 152.077301
current_seq = 770
count = 52
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.060989/769, current 152.077927/770: elapsed=16926.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.077927
last_received_ts = 152.077301
last_seq = 770
current_ts = 152.094864
current_received_ts = 152.094299
current_seq = 771
count = 53
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.077927/770, current 152.094864/771: elapsed=16944.0us expected=16964.9us +- 84.8us, error 0.1%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.094864
last_received_ts = 152.094299
last_seq = 771
current_ts = 152.111801
current_received_ts = 152.111237
current_seq = 772
count = 54
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.094864/771, current 152.111801/772: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.111801
last_received_ts = 152.111237
last_seq = 772
current_ts = 152.128738
current_received_ts = 152.128174
current_seq = 773
count = 55
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.111801/772, current 152.128738/773: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.128738
last_received_ts = 152.128174
last_seq = 773
current_ts = 152.145660
current_received_ts = 152.145111
current_seq = 774
count = 56
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.128738/773, current 152.145660/774: elapsed=16930.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.145660
last_received_ts = 152.145111
last_seq = 774
current_ts = 152.162598
current_received_ts = 152.162064
current_seq = 775
count = 57
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.145660/774, current 152.162598/775: elapsed=16939.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.162598
last_received_ts = 152.162064
last_seq = 775
current_ts = 152.179535
current_received_ts = 152.178986
current_seq = 776
count = 58
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.162598/775, current 152.179535/776: elapsed=16930.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.179535
last_received_ts = 152.178986
last_seq = 776
current_ts = 152.196472
current_received_ts = 152.195923
current_seq = 777
count = 59
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.179535/776, current 152.196472/777: elapsed=16938.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.196472
last_received_ts = 152.195923
last_seq = 777
current_ts = 152.213409
current_received_ts = 152.212845
current_seq = 778
count = 60
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.196472/777, current 152.213409/778: elapsed=16937.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.213409
last_received_ts = 152.212845
last_seq = 778
current_ts = 152.230331
current_received_ts = 152.229782
current_seq = 779
count = 61
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.213409/778, current 152.230331/779: elapsed=16932.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.230331
last_received_ts = 152.229782
last_seq = 779
current_ts = 152.247269
current_received_ts = 152.246628
current_seq = 780
count = 62
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.230331/779, current 152.247269/780: elapsed=16929.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.247269
last_received_ts = 152.246628
last_seq = 780
current_ts = 152.264206
current_received_ts = 152.263657
current_seq = 781
count = 63
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.247269/780, current 152.264206/781: elapsed=16944.0us expected=16964.9us +- 84.8us, error 0.1%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.264206
last_received_ts = 152.263657
last_seq = 781
current_ts = 152.281143
current_received_ts = 152.280563
current_seq = 782
count = 64
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.264206/781, current 152.281143/782: elapsed=16927.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.281143
last_received_ts = 152.280563
last_seq = 782
current_ts = 152.298080
current_received_ts = 152.297501
current_seq = 783
count = 65
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.281143/782, current 152.298080/783: elapsed=16941.0us expected=16964.9us +- 84.8us, error 0.1%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.298080
last_received_ts = 152.297501
last_seq = 783
current_ts = 152.315018
current_received_ts = 152.314453
current_seq = 784
count = 66
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.298080/783, current 152.315018/784: elapsed=16936.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.315018
last_received_ts = 152.314453
last_seq = 784
current_ts = 152.331955
current_received_ts = 152.331390
current_seq = 785
count = 67
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.315018/784, current 152.331955/785: elapsed=16935.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.331955
last_received_ts = 152.331390
last_seq = 785
current_ts = 152.348892
current_received_ts = 152.348328
current_seq = 786
count = 68
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.331955/785, current 152.348892/786: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.348892
last_received_ts = 152.348328
last_seq = 786
current_ts = 152.365814
current_received_ts = 152.365265
current_seq = 787
count = 69
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.348892/786, current 152.365814/787: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.365814
last_received_ts = 152.365265
last_seq = 787
current_ts = 152.382751
current_received_ts = 152.382187
current_seq = 788
count = 70
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.365814/787, current 152.382751/788: elapsed=16936.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.382751
last_received_ts = 152.382187
last_seq = 788
current_ts = 152.399689
current_received_ts = 152.399124
current_seq = 789
count = 71
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.382751/788, current 152.399689/789: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.399689
last_received_ts = 152.399124
last_seq = 789
current_ts = 152.416626
current_received_ts = 152.416077
current_seq = 790
count = 72
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.399689/789, current 152.416626/790: elapsed=16936.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.416626
last_received_ts = 152.416077
last_seq = 790
current_ts = 152.433563
current_received_ts = 152.433029
current_seq = 791
count = 73
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.416626/790, current 152.433563/791: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.433563
last_received_ts = 152.433029
last_seq = 791
current_ts = 152.450500
current_received_ts = 152.449875
current_seq = 792
count = 74
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.433563/791, current 152.450500/792: elapsed=16942.0us expected=16964.9us +- 84.8us, error 0.1%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.450500
last_received_ts = 152.449875
last_seq = 792
current_ts = 152.467422
current_received_ts = 152.466858
current_seq = 793
count = 75
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.450500/792, current 152.467422/793: elapsed=16928.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.467422
last_received_ts = 152.466858
last_seq = 793
current_ts = 152.484360
current_received_ts = 152.483780
current_seq = 794
count = 76
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.467422/793, current 152.484360/794: elapsed=16934.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.484360
last_received_ts = 152.483780
last_seq = 794
current_ts = 152.501282
current_received_ts = 152.500732
current_seq = 795
count = 77
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.484360/794, current 152.501282/795: elapsed=16926.0us expected=16964.9us +- 84.8us, error 0.2%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.501282
last_received_ts = 152.500732
last_seq = 795
current_ts = 152.518204
current_received_ts = 152.517563
current_seq = 796
count = 78
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.501282/795, current 152.518204/796: elapsed=16912.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.518204
last_received_ts = 152.517563
last_seq = 796
current_ts = 152.535110
current_received_ts = 152.534546
current_seq = 797
count = 79
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.518204/796, current 152.535110/797: elapsed=16910.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.535110
last_received_ts = 152.534546
last_seq = 797
current_ts = 152.552017
current_received_ts = 152.551437
current_seq = 798
count = 80
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.535110/797, current 152.552017/798: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.552017
last_received_ts = 152.551437
last_seq = 798
current_ts = 152.568924
current_received_ts = 152.568314
current_seq = 799
count = 81
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.552017/798, current 152.568924/799: elapsed=16902.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.568924
last_received_ts = 152.568314
last_seq = 799
current_ts = 152.585831
current_received_ts = 152.585266
current_seq = 800
count = 82
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.568924/799, current 152.585831/800: elapsed=16916.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.585831
last_received_ts = 152.585266
last_seq = 800
current_ts = 152.602737
current_received_ts = 152.602158
current_seq = 801
count = 83
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.585831/800, current 152.602737/801: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.602737
last_received_ts = 152.602158
last_seq = 801
current_ts = 152.619659
current_received_ts = 152.619095
current_seq = 802
count = 84
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.602737/801, current 152.619659/802: elapsed=16911.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.619659
last_received_ts = 152.619095
last_seq = 802
current_ts = 152.636566
current_received_ts = 152.636047
current_seq = 803
count = 85
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.619659/802, current 152.636566/803: elapsed=16906.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.636566
last_received_ts = 152.636047
last_seq = 803
current_ts = 152.653458
current_received_ts = 152.652878
current_seq = 804
count = 86
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.636566/803, current 152.653458/804: elapsed=16902.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.653458
last_received_ts = 152.652878
last_seq = 804
current_ts = 152.670380
current_received_ts = 152.669815
current_seq = 805
count = 87
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.653458/804, current 152.670380/805: elapsed=16911.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.670380
last_received_ts = 152.669815
last_seq = 805
current_ts = 152.687286
current_received_ts = 152.686722
current_seq = 806
count = 88
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.670380/805, current 152.687286/806: elapsed=16913.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.687286
last_received_ts = 152.686722
last_seq = 806
current_ts = 152.704193
current_received_ts = 152.703613
current_seq = 807
count = 89
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.687286/806, current 152.704193/807: elapsed=16910.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.704193
last_received_ts = 152.703613
last_seq = 807
current_ts = 152.721100
current_received_ts = 152.720520
current_seq = 808
count = 90
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.704193/807, current 152.721100/808: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.721100
last_received_ts = 152.720520
last_seq = 808
current_ts = 152.738007
current_received_ts = 152.737457
current_seq = 809
count = 91
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.721100/808, current 152.738007/809: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.738007
last_received_ts = 152.737457
last_seq = 809
current_ts = 152.754913
current_received_ts = 152.754333
current_seq = 810
count = 92
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.738007/809, current 152.754913/810: elapsed=16906.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.754913
last_received_ts = 152.754333
last_seq = 810
current_ts = 152.771835
current_received_ts = 152.771255
current_seq = 811
count = 93
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.754913/810, current 152.771835/811: elapsed=16912.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.771835
last_received_ts = 152.771255
last_seq = 811
current_ts = 152.788742
current_received_ts = 152.788147
current_seq = 812
count = 94
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.771835/811, current 152.788742/812: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.788742
last_received_ts = 152.788147
last_seq = 812
current_ts = 152.805634
current_received_ts = 152.805099
current_seq = 813
count = 95
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.788742/812, current 152.805634/813: elapsed=16902.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.805634
last_received_ts = 152.805099
last_seq = 813
current_ts = 152.822556
current_received_ts = 152.821991
current_seq = 814
count = 96
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.805634/813, current 152.822556/814: elapsed=16916.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.822556
last_received_ts = 152.821991
last_seq = 814
current_ts = 152.839462
current_received_ts = 152.838837
current_seq = 815
count = 97
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.822556/814, current 152.839462/815: elapsed=16901.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.839462
last_received_ts = 152.838837
last_seq = 815
current_ts = 152.856369
current_received_ts = 152.855789
current_seq = 816
count = 98
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.839462/815, current 152.856369/816: elapsed=16917.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.856369
last_received_ts = 152.855789
last_seq = 816
current_ts = 152.873276
current_received_ts = 152.872696
current_seq = 817
count = 99
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.856369/816, current 152.873276/817: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.873276
last_received_ts = 152.872696
last_seq = 817
current_ts = 152.890182
current_received_ts = 152.889618
current_seq = 818
count = 100
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.873276/817, current 152.890182/818: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.890182
last_received_ts = 152.889618
last_seq = 818
current_ts = 152.907104
current_received_ts = 152.906509
current_seq = 819
count = 101
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.890182/818, current 152.907104/819: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.907104
last_received_ts = 152.906509
last_seq = 819
current_ts = 152.924011
current_received_ts = 152.923431
current_seq = 820
count = 102
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.907104/819, current 152.924011/820: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.924011
last_received_ts = 152.923431
last_seq = 820
current_ts = 152.940918
current_received_ts = 152.940338
current_seq = 821
count = 103
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.924011/820, current 152.940918/821: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.940918
last_received_ts = 152.940338
last_seq = 821
current_ts = 152.957825
current_received_ts = 152.957245
current_seq = 822
count = 104
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.940918/821, current 152.957825/822: elapsed=16910.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.957825
last_received_ts = 152.957245
last_seq = 822
current_ts = 152.974731
current_received_ts = 152.974167
current_seq = 823
count = 105
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.957825/822, current 152.974731/823: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.974731
last_received_ts = 152.974167
last_seq = 823
current_ts = 152.991638
current_received_ts = 152.991074
current_seq = 824
count = 106
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.974731/823, current 152.991638/824: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 152.991638
last_received_ts = 152.991074
last_seq = 824
current_ts = 153.008545
current_received_ts = 153.007965
current_seq = 825
count = 107
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 152.991638/824, current 153.008545/825: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.008545
last_received_ts = 153.007965
last_seq = 825
current_ts = 153.025452
current_received_ts = 153.024872
current_seq = 826
count = 108
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.008545/825, current 153.025452/826: elapsed=16904.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.025452
last_received_ts = 153.024872
last_seq = 826
current_ts = 153.042374
current_received_ts = 153.041794
current_seq = 827
count = 109
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.025452/826, current 153.042374/827: elapsed=16914.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.042374
last_received_ts = 153.041794
last_seq = 827
current_ts = 153.059280
current_received_ts = 153.058701
current_seq = 828
count = 110
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.042374/827, current 153.059280/828: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.059280
last_received_ts = 153.058701
last_seq = 828
current_ts = 153.076187
current_received_ts = 153.075653
current_seq = 829
count = 111
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.059280/828, current 153.076187/829: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.076187
last_received_ts = 153.075653
last_seq = 829
current_ts = 153.093094
current_received_ts = 153.092560
current_seq = 830
count = 112
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.076187/829, current 153.093094/830: elapsed=16911.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.093094
last_received_ts = 153.092560
last_seq = 830
current_ts = 153.110001
current_received_ts = 153.109741
current_seq = 831
count = 113
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.093094/830, current 153.110001/831: elapsed=16898.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.110001
last_received_ts = 153.109741
last_seq = 831
current_ts = 153.126907
current_received_ts = 153.126404
current_seq = 832
count = 114
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.110001/831, current 153.126907/832: elapsed=16917.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.126907
last_received_ts = 153.126404
last_seq = 832
current_ts = 153.143814
current_received_ts = 153.143311
current_seq = 833
count = 115
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.126907/832, current 153.143814/833: elapsed=16910.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.143814
last_received_ts = 153.143311
last_seq = 833
current_ts = 153.160721
current_received_ts = 153.160217
current_seq = 834
count = 116
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.143814/833, current 153.160721/834: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.160721
last_received_ts = 153.160217
last_seq = 834
current_ts = 153.177643
current_received_ts = 153.177109
current_seq = 835
count = 117
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.160721/834, current 153.177643/835: elapsed=16914.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.177643
last_received_ts = 153.177109
last_seq = 835
current_ts = 153.194550
current_received_ts = 153.193985
current_seq = 836
count = 118
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.177643/835, current 153.194550/836: elapsed=16903.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.194550
last_received_ts = 153.193985
last_seq = 836
current_ts = 153.211441
current_received_ts = 153.210892
current_seq = 837
count = 119
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.194550/836, current 153.211441/837: elapsed=16904.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.211441
last_received_ts = 153.210892
last_seq = 837
current_ts = 153.228363
current_received_ts = 153.227768
current_seq = 838
count = 120
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.211441/837, current 153.228363/838: elapsed=16919.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.228363
last_received_ts = 153.227768
last_seq = 838
current_ts = 153.245255
current_received_ts = 153.244705
current_seq = 839
count = 121
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.228363/838, current 153.245255/839: elapsed=16894.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.245255
last_received_ts = 153.244705
last_seq = 839
current_ts = 153.262177
current_received_ts = 153.261612
current_seq = 840
count = 122
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.245255/839, current 153.262177/840: elapsed=16914.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.262177
last_received_ts = 153.261612
last_seq = 840
current_ts = 153.279083
current_received_ts = 153.278519
current_seq = 841
count = 123
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.262177/840, current 153.279083/841: elapsed=16912.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.279083
last_received_ts = 153.278519
last_seq = 841
current_ts = 153.295990
current_received_ts = 153.295410
current_seq = 842
count = 124
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.279083/841, current 153.295990/842: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.295990
last_received_ts = 153.295410
last_seq = 842
current_ts = 153.312912
current_received_ts = 153.312347
current_seq = 843
count = 125
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.295990/842, current 153.312912/843: elapsed=16910.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.312912
last_received_ts = 153.312347
last_seq = 843
current_ts = 153.329819
current_received_ts = 153.329254
current_seq = 844
count = 126
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.312912/843, current 153.329819/844: elapsed=16907.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.329819
last_received_ts = 153.329254
last_seq = 844
current_ts = 153.346725
current_received_ts = 153.346161
current_seq = 845
count = 127
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.329819/844, current 153.346725/845: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.346725
last_received_ts = 153.346161
last_seq = 845
current_ts = 153.363632
current_received_ts = 153.363083
current_seq = 846
count = 128
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.346725/845, current 153.363632/846: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.363632
last_received_ts = 153.363083
last_seq = 846
current_ts = 153.380539
current_received_ts = 153.379974
current_seq = 847
count = 129
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.363632/846, current 153.380539/847: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.380539
last_received_ts = 153.379974
last_seq = 847
current_ts = 153.397446
current_received_ts = 153.396881
current_seq = 848
count = 130
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.380539/847, current 153.397446/848: elapsed=16904.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.397446
last_received_ts = 153.396881
last_seq = 848
current_ts = 153.414352
current_received_ts = 153.413788
current_seq = 849
count = 131
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.397446/848, current 153.414352/849: elapsed=16913.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.414352
last_received_ts = 153.413788
last_seq = 849
current_ts = 153.431259
current_received_ts = 153.430695
current_seq = 850
count = 132
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.414352/849, current 153.431259/850: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.431259
last_received_ts = 153.430695
last_seq = 850
current_ts = 153.448166
current_received_ts = 153.447617
current_seq = 851
count = 133
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.431259/850, current 153.448166/851: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.448166
last_received_ts = 153.447617
last_seq = 851
current_ts = 153.465088
current_received_ts = 153.464523
current_seq = 852
count = 134
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.448166/851, current 153.465088/852: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.465088
last_received_ts = 153.464523
last_seq = 852
current_ts = 153.481995
current_received_ts = 153.481430
current_seq = 853
count = 135
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.465088/852, current 153.481995/853: elapsed=16908.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.481995
last_received_ts = 153.481430
last_seq = 853
current_ts = 153.498901
current_received_ts = 153.498322
current_seq = 854
count = 136
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.481995/853, current 153.498901/854: elapsed=16909.0us expected=16964.9us +- 84.8us, error 0.3%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.498901
last_received_ts = 153.498322
last_seq = 854
current_ts = 153.515778
current_received_ts = 153.515228
current_seq = 855
count = 137
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.498901/854, current 153.515778/855: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.515778
last_received_ts = 153.515228
last_seq = 855
current_ts = 153.532669
current_received_ts = 153.532104
current_seq = 856
count = 138
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.515778/855, current 153.532669/856: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.532669
last_received_ts = 153.532104
last_seq = 856
current_ts = 153.549561
current_received_ts = 153.548996
current_seq = 857
count = 139
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.532669/856, current 153.549561/857: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.549561
last_received_ts = 153.548996
last_seq = 857
current_ts = 153.566437
current_received_ts = 153.565872
current_seq = 858
count = 140
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.549561/857, current 153.566437/858: elapsed=16881.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.566437
last_received_ts = 153.565872
last_seq = 858
current_ts = 153.583328
current_received_ts = 153.582764
current_seq = 859
count = 141
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.566437/858, current 153.583328/859: elapsed=16890.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.583328
last_received_ts = 153.582764
last_seq = 859
current_ts = 153.600204
current_received_ts = 153.599640
current_seq = 860
count = 142
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.583328/859, current 153.600204/860: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.600204
last_received_ts = 153.599640
last_seq = 860
current_ts = 153.617096
current_received_ts = 153.616531
current_seq = 861
count = 143
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.600204/860, current 153.617096/861: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.617096
last_received_ts = 153.616531
last_seq = 861
current_ts = 153.633987
current_received_ts = 153.633408
current_seq = 862
count = 144
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.617096/861, current 153.633987/862: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.633987
last_received_ts = 153.633408
last_seq = 862
current_ts = 153.650864
current_received_ts = 153.650299
current_seq = 863
count = 145
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.633987/862, current 153.650864/863: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.650864
last_received_ts = 153.650299
last_seq = 863
current_ts = 153.667755
current_received_ts = 153.667191
current_seq = 864
count = 146
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.650864/863, current 153.667755/864: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.667755
last_received_ts = 153.667191
last_seq = 864
current_ts = 153.684647
current_received_ts = 153.684097
current_seq = 865
count = 147
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.667755/864, current 153.684647/865: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.684647
last_received_ts = 153.684097
last_seq = 865
current_ts = 153.701523
current_received_ts = 153.700958
current_seq = 866
count = 148
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.684647/865, current 153.701523/866: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.701523
last_received_ts = 153.700958
last_seq = 866
current_ts = 153.718414
current_received_ts = 153.717804
current_seq = 867
count = 149
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.701523/866, current 153.718414/867: elapsed=16889.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.718414
last_received_ts = 153.717804
last_seq = 867
current_ts = 153.735291
current_received_ts = 153.734741
current_seq = 868
count = 150
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.718414/867, current 153.735291/868: elapsed=16882.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.735291
last_received_ts = 153.734741
last_seq = 868
current_ts = 153.752182
current_received_ts = 153.751617
current_seq = 869
count = 151
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.735291/868, current 153.752182/869: elapsed=16881.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.752182
last_received_ts = 153.751617
last_seq = 869
current_ts = 153.769073
current_received_ts = 153.768509
current_seq = 870
count = 152
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.752182/869, current 153.769073/870: elapsed=16892.0us expected=16964.9us +- 84.8us, error 0.4%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.769073
last_received_ts = 153.768509
last_seq = 870
current_ts = 153.785950
current_received_ts = 153.785385
current_seq = 871
count = 153
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.769073/870, current 153.785950/871: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.785950
last_received_ts = 153.785385
last_seq = 871
current_ts = 153.802841
current_received_ts = 153.802292
current_seq = 872
count = 154
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.785950/871, current 153.802841/872: elapsed=16884.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.802841
last_received_ts = 153.802292
last_seq = 872
current_ts = 153.819733
current_received_ts = 153.819168
current_seq = 873
count = 155
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.802841/872, current 153.819733/873: elapsed=16887.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.819733
last_received_ts = 153.819168
last_seq = 873
current_ts = 153.836609
current_received_ts = 153.836075
current_seq = 874
count = 156
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.819733/873, current 153.836609/874: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.836609
last_received_ts = 153.836075
last_seq = 874
current_ts = 153.853500
current_received_ts = 153.852936
current_seq = 875
count = 157
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.836609/874, current 153.853500/875: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.853500
last_received_ts = 153.852936
last_seq = 875
current_ts = 153.870377
current_received_ts = 153.869827
current_seq = 876
count = 158
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.853500/875, current 153.870377/876: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.870377
last_received_ts = 153.869827
last_seq = 876
current_ts = 153.887268
current_received_ts = 153.886703
current_seq = 877
count = 159
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.870377/876, current 153.887268/877: elapsed=16888.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.887268
last_received_ts = 153.886703
last_seq = 877
current_ts = 153.904160
current_received_ts = 153.903564
current_seq = 878
count = 160
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.887268/877, current 153.904160/878: elapsed=16884.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.904160
last_received_ts = 153.903564
last_seq = 878
current_ts = 153.921036
current_received_ts = 153.920471
current_seq = 879
count = 161
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.904160/878, current 153.921036/879: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.921036
last_received_ts = 153.920471
last_seq = 879
current_ts = 153.937927
current_received_ts = 153.937363
current_seq = 880
count = 162
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.921036/879, current 153.937927/880: elapsed=16885.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.937927
last_received_ts = 153.937363
last_seq = 880
current_ts = 153.954803
current_received_ts = 153.954254
current_seq = 881
count = 163
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.937927/880, current 153.954803/881: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.954803
last_received_ts = 153.954254
last_seq = 881
current_ts = 153.971695
current_received_ts = 153.971130
current_seq = 882
count = 164
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.954803/881, current 153.971695/882: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.971695
last_received_ts = 153.971130
last_seq = 882
current_ts = 153.988586
current_received_ts = 153.988052
current_seq = 883
count = 165
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.971695/882, current 153.988586/883: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 153.988586
last_received_ts = 153.988052
last_seq = 883
current_ts = 154.005463
current_received_ts = 154.004852
current_seq = 884
count = 166
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 153.988586/883, current 154.005463/884: elapsed=16886.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: name = flip
last_ts = 154.005463
last_received_ts = 154.004852
last_seq = 884
current_ts = 154.022354
current_received_ts = 154.021774
current_seq = 885
count = 167
seq_step = 1
(kms_flip:2656) DEBUG: flip ts/seq: last 154.005463/884, current 154.022354/885: elapsed=16879.0us expected=16964.9us +- 84.8us, error 0.5%
(kms_flip:2656) DEBUG: inconsistent flip ts/seq: last 154.005463/884, current 154.022354/885: elapsed=16879.0us expected=16964.9us
(kms_flip:2656) DEBUG: expected 66087, counted 167, encoder type 1
(kms_flip:2656) DEBUG: dropped frames, expected 66087, counted 167, encoder type 1
(kms_flip:2656) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2656) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2656) igt_core-INFO: Stack trace:
(kms_flip:2656) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2656) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2656) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2656) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2656) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2656) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2656) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2656) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (6.401s)
Dmesg
<6> [150.578512] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [150.579326] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:84]
<7> [150.579545] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [150.615822] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:47:pipe A]
<7> [150.616078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [150.616564] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [150.617027] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [150.617490] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [150.617846] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [150.618330] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [150.618720] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [150.619201] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [150.619442] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [150.619691] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [150.619971] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [150.620217] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [150.620480] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [150.620733] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [150.620984] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [150.621215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [150.621504] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [150.621742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [150.622029] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [150.622283] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [150.622521] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [150.622798] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [150.623042] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [150.623267] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [150.623514] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [150.623753] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [150.624002] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [150.624252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [150.624489] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [150.624722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [150.624996] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [150.625221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [150.625432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [150.625644] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [150.625868] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [150.626081] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [150.626292] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [150.626503] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [150.626714] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [150.626937] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:47:pipe A] fastset requirement not met, forcing full modeset
<7> [150.627150] i915 0000:00:02.0: [drm:intel_unreference_shared_dpll_crtc [i915]] [CRTC:47:pipe A] releasing PCH DPLL A
<7> [150.627419] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [150.627643] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [150.627882] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:47:pipe A] enable: no [modeset]
<7> [150.628094] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:primary A] fb: [NOFB], visible: no
<7> [150.628434] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [150.646733] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [150.646970] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [150.647177] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [150.663508] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:47:pipe A]
<7> [150.663950] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling PCH DPLL A
<7> [150.664623] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [150.665032] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [150.665449] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [150.665941] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [150.666478] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:47:pipe A]
<7> [150.666883] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [150.667101] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [150.667144] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:64:VGA-1]
<7> [150.667264] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:64:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [150.667536] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [150.667744] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [150.667946] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [150.668184] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [150.668420] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [150.668626] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [150.668832] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [150.669036] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)
<7> [150.669284] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [150.669563] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [150.669770] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [150.669975] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [150.670212] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [150.670450] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [150.670656] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [150.670861] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [150.671088] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [150.671336] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [150.671541] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [150.671746] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [150.671951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [150.672186] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [150.672431] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [150.672637] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [150.672842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [150.673089] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [150.673346] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [150.673551] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [150.673756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [150.673972] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [150.674202] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [150.674452] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [150.674659] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [150.674864] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [150.675104] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [150.675341] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [150.675547] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [150.675752] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in dpll_hw_state
<7> [150.675957] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [150.676222] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [150.676468] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [150.676683] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [150.676895] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [150.677155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [150.677396] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [150.677602] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [150.677808] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] fastset requirement not met, forcing full modeset
<7> [150.678110] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:48:primary B] min cdclk (64800 kHz) > [CRTC:63:pipe B] min cdclk (0 kHz)
<7> [150.678337] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [150.678541] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [150.678748] i915 0000:00:02.0: [drm:intel_find_shared_dpll [i915]] [CRTC:63:pipe B] allocated PCH DPLL A
<7> [150.678976] i915 0000:00:02.0: [drm:intel_reference_shared_dpll_crtc [i915]] [CRTC:63:pipe B] reserving PCH DPLL A
<7> [150.679207] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:63:pipe B] enable: yes [modeset]
<7> [150.679429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [150.679634] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [150.679838] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [150.680094] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [150.680311] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [150.680516] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [150.680720] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64
<7> [150.680950] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [150.681186] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [150.681390] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [150.681594] 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> [150.681800] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: -1, vmax vblank: -2, vmin vtotal: 1, vmax vtotal: 0
<7> [150.682029] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [150.682306] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [150.682517] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [150.682723] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [150.682959] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [150.683185] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [150.683391] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [150.683596] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [150.683811] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [150.683912] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [150.684230] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [150.684508] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [150.684718] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [150.684964] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [150.685181] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [150.685386] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [150.685590] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [150.685794] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:48:primary B] fb: [FB:84] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [150.686041] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [150.686258] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [150.687846] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [150.688080] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [150.688284] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [150.688484] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [150.689251] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [150.690412] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [150.690624] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [150.691626] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [150.691967] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [150.692183] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [150.692403] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:63:pipe B]
<7> [150.692702] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enabling PCH DPLL A
<7> [150.744836] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [150.745376] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:63:pipe B]
<6> [156.981067] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2025-03-18 12:02:16