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

shard-tglu-10

IGT-Version: 1.30-g80f0cbff4 (x86_64) (Linux: 6.14.0-rc6-CI_DRM_16261-g003c44ec0b7d+ x86_64)

Using IGT_SRANDOM=1741671610 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8334.9us +- 3.931us accuracy 0.14%
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 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (5.536s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8295.6us +- 3.204us accuracy 0.12%
vblank interval differs from modeline! expected 8334.6us, measured 8296us +- 3.204us, difference 39.0us (12.2 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 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (11.020s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8322.5us +- 2.781us accuracy 0.10%
vblank interval differs from modeline! expected 8334.6us, measured 8322us +- 2.781us, difference 12.1us (4.3 sigma)
Dynamic subtest C-HDMI-A1: SUCCESS (7.816s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8327.5us +- 3.464us accuracy 0.12%
vblank interval differs from modeline! expected 8334.6us, measured 8328us +- 3.464us, difference 7.1us (2.0 sigma)
Dynamic subtest D-HDMI-A1: SUCCESS (7.811s)
Subtest plain-flip-ts-check: FAIL (32.194s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2430) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2430) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2430) DEBUG: flip ts/seq: last 200.148865/16152, current 200.157211/16153: elapsed=8340.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.157211
last_received_ts = 200.156998
last_seq = 16153
current_ts = 200.165543
current_received_ts = 200.165253
current_seq = 16154
count = 118
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.157211/16153, current 200.165543/16154: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.165543
last_received_ts = 200.165253
last_seq = 16154
current_ts = 200.173874
current_received_ts = 200.173584
current_seq = 16155
count = 119
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.165543/16154, current 200.173874/16155: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.173874
last_received_ts = 200.173584
last_seq = 16155
current_ts = 200.182205
current_received_ts = 200.181885
current_seq = 16156
count = 120
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.173874/16155, current 200.182205/16156: elapsed=8337.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.182205
last_received_ts = 200.181885
last_seq = 16156
current_ts = 200.190536
current_received_ts = 200.190140
current_seq = 16157
count = 121
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.182205/16156, current 200.190536/16157: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.190536
last_received_ts = 200.190140
last_seq = 16157
current_ts = 200.198883
current_received_ts = 200.198471
current_seq = 16158
count = 122
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.190536/16157, current 200.198883/16158: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.198883
last_received_ts = 200.198471
last_seq = 16158
current_ts = 200.207214
current_received_ts = 200.206848
current_seq = 16159
count = 123
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.198883/16158, current 200.207214/16159: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.207214
last_received_ts = 200.206848
last_seq = 16159
current_ts = 200.215546
current_received_ts = 200.215134
current_seq = 16160
count = 124
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.207214/16159, current 200.215546/16160: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.215546
last_received_ts = 200.215134
last_seq = 16160
current_ts = 200.223877
current_received_ts = 200.223526
current_seq = 16161
count = 125
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.215546/16160, current 200.223877/16161: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.223877
last_received_ts = 200.223526
last_seq = 16161
current_ts = 200.232208
current_received_ts = 200.231827
current_seq = 16162
count = 126
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.223877/16161, current 200.232208/16162: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.232208
last_received_ts = 200.231827
last_seq = 16162
current_ts = 200.240555
current_received_ts = 200.240189
current_seq = 16163
count = 127
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.232208/16162, current 200.240555/16163: elapsed=8339.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.240555
last_received_ts = 200.240189
last_seq = 16163
current_ts = 200.248886
current_received_ts = 200.248550
current_seq = 16164
count = 128
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.240555/16163, current 200.248886/16164: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.248886
last_received_ts = 200.248550
last_seq = 16164
current_ts = 200.257217
current_received_ts = 200.256912
current_seq = 16165
count = 129
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.248886/16164, current 200.257217/16165: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.257217
last_received_ts = 200.256912
last_seq = 16165
current_ts = 200.265549
current_received_ts = 200.267044
current_seq = 16166
count = 130
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.257217/16165, current 200.265549/16166: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.265549
last_received_ts = 200.267044
last_seq = 16166
current_ts = 200.273880
current_received_ts = 200.273499
current_seq = 16167
count = 131
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.265549/16166, current 200.273880/16167: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.273880
last_received_ts = 200.273499
last_seq = 16167
current_ts = 200.282211
current_received_ts = 200.281845
current_seq = 16168
count = 132
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.273880/16167, current 200.282211/16168: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.282211
last_received_ts = 200.281845
last_seq = 16168
current_ts = 200.290543
current_received_ts = 200.290192
current_seq = 16169
count = 133
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.282211/16168, current 200.290543/16169: elapsed=8337.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.290543
last_received_ts = 200.290192
last_seq = 16169
current_ts = 200.298874
current_received_ts = 200.298523
current_seq = 16170
count = 134
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.290543/16169, current 200.298874/16170: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.298874
last_received_ts = 200.298523
last_seq = 16170
current_ts = 200.307205
current_received_ts = 200.306854
current_seq = 16171
count = 135
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.298874/16170, current 200.307205/16171: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.307205
last_received_ts = 200.306854
last_seq = 16171
current_ts = 200.315536
current_received_ts = 200.315231
current_seq = 16172
count = 136
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.307205/16171, current 200.315536/16172: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.315536
last_received_ts = 200.315231
last_seq = 16172
current_ts = 200.323868
current_received_ts = 200.323578
current_seq = 16173
count = 137
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.315536/16172, current 200.323868/16173: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.323868
last_received_ts = 200.323578
last_seq = 16173
current_ts = 200.332199
current_received_ts = 200.331894
current_seq = 16174
count = 138
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.323868/16173, current 200.332199/16174: elapsed=8325.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.332199
last_received_ts = 200.331894
last_seq = 16174
current_ts = 200.340530
current_received_ts = 200.340286
current_seq = 16175
count = 139
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.332199/16174, current 200.340530/16175: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.340530
last_received_ts = 200.340286
last_seq = 16175
current_ts = 200.348862
current_received_ts = 200.348648
current_seq = 16176
count = 140
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.340530/16175, current 200.348862/16176: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.348862
last_received_ts = 200.348648
last_seq = 16176
current_ts = 200.357193
current_received_ts = 200.356934
current_seq = 16177
count = 141
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.348862/16176, current 200.357193/16177: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.357193
last_received_ts = 200.356934
last_seq = 16177
current_ts = 200.365524
current_received_ts = 200.365265
current_seq = 16178
count = 142
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.357193/16177, current 200.365524/16178: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.365524
last_received_ts = 200.365265
last_seq = 16178
current_ts = 200.373856
current_received_ts = 200.373672
current_seq = 16179
count = 143
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.365524/16178, current 200.373856/16179: elapsed=8335.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.373856
last_received_ts = 200.373672
last_seq = 16179
current_ts = 200.382187
current_received_ts = 200.381973
current_seq = 16180
count = 144
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.373856/16179, current 200.382187/16180: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.382187
last_received_ts = 200.381973
last_seq = 16180
current_ts = 200.390518
current_received_ts = 200.390259
current_seq = 16181
count = 145
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.382187/16180, current 200.390518/16181: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.390518
last_received_ts = 200.390259
last_seq = 16181
current_ts = 200.398834
current_received_ts = 200.398529
current_seq = 16182
count = 146
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.390518/16181, current 200.398834/16182: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.398834
last_received_ts = 200.398529
last_seq = 16182
current_ts = 200.407166
current_received_ts = 200.406967
current_seq = 16183
count = 147
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.398834/16182, current 200.407166/16183: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.407166
last_received_ts = 200.406967
last_seq = 16183
current_ts = 200.415497
current_received_ts = 200.415192
current_seq = 16184
count = 148
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.407166/16183, current 200.415497/16184: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.415497
last_received_ts = 200.415192
last_seq = 16184
current_ts = 200.423828
current_received_ts = 200.423523
current_seq = 16185
count = 149
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.415497/16184, current 200.423828/16185: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.423828
last_received_ts = 200.423523
last_seq = 16185
current_ts = 200.432159
current_received_ts = 200.431839
current_seq = 16186
count = 150
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.423828/16185, current 200.432159/16186: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.432159
last_received_ts = 200.431839
last_seq = 16186
current_ts = 200.440491
current_received_ts = 200.440231
current_seq = 16187
count = 151
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.432159/16186, current 200.440491/16187: elapsed=8326.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.440491
last_received_ts = 200.440231
last_seq = 16187
current_ts = 200.448822
current_received_ts = 200.448517
current_seq = 16188
count = 152
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.440491/16187, current 200.448822/16188: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.448822
last_received_ts = 200.448517
last_seq = 16188
current_ts = 200.457153
current_received_ts = 200.456863
current_seq = 16189
count = 153
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.448822/16188, current 200.457153/16189: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.457153
last_received_ts = 200.456863
last_seq = 16189
current_ts = 200.465485
current_received_ts = 200.465271
current_seq = 16190
count = 154
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.457153/16189, current 200.465485/16190: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.465485
last_received_ts = 200.465271
last_seq = 16190
current_ts = 200.473816
current_received_ts = 200.473618
current_seq = 16191
count = 155
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.465485/16190, current 200.473816/16191: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.473816
last_received_ts = 200.473618
last_seq = 16191
current_ts = 200.482147
current_received_ts = 200.481949
current_seq = 16192
count = 156
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.473816/16191, current 200.482147/16192: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.482147
last_received_ts = 200.481949
last_seq = 16192
current_ts = 200.490479
current_received_ts = 200.490280
current_seq = 16193
count = 157
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.482147/16192, current 200.490479/16193: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.490479
last_received_ts = 200.490280
last_seq = 16193
current_ts = 200.498795
current_received_ts = 200.498581
current_seq = 16194
count = 158
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.490479/16193, current 200.498795/16194: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.498795
last_received_ts = 200.498581
last_seq = 16194
current_ts = 200.507141
current_received_ts = 200.506897
current_seq = 16195
count = 159
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.498795/16194, current 200.507141/16195: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.507141
last_received_ts = 200.506897
last_seq = 16195
current_ts = 200.515472
current_received_ts = 200.515182
current_seq = 16196
count = 160
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.507141/16195, current 200.515472/16196: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.515472
last_received_ts = 200.515182
last_seq = 16196
current_ts = 200.523788
current_received_ts = 200.523529
current_seq = 16197
count = 161
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.515472/16196, current 200.523788/16197: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.523788
last_received_ts = 200.523529
last_seq = 16197
current_ts = 200.532120
current_received_ts = 200.531921
current_seq = 16198
count = 162
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.523788/16197, current 200.532120/16198: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.532120
last_received_ts = 200.531921
last_seq = 16198
current_ts = 200.540466
current_received_ts = 200.540176
current_seq = 16199
count = 163
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.532120/16198, current 200.540466/16199: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.540466
last_received_ts = 200.540176
last_seq = 16199
current_ts = 200.548782
current_received_ts = 200.548523
current_seq = 16200
count = 164
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.540466/16199, current 200.548782/16200: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.548782
last_received_ts = 200.548523
last_seq = 16200
current_ts = 200.557114
current_received_ts = 200.556900
current_seq = 16201
count = 165
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.548782/16200, current 200.557114/16201: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.557114
last_received_ts = 200.556900
last_seq = 16201
current_ts = 200.565445
current_received_ts = 200.565170
current_seq = 16202
count = 166
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.557114/16201, current 200.565445/16202: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.565445
last_received_ts = 200.565170
last_seq = 16202
current_ts = 200.573776
current_received_ts = 200.573502
current_seq = 16203
count = 167
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.565445/16202, current 200.573776/16203: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.573776
last_received_ts = 200.573502
last_seq = 16203
current_ts = 200.582108
current_received_ts = 200.581848
current_seq = 16204
count = 168
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.573776/16203, current 200.582108/16204: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.582108
last_received_ts = 200.581848
last_seq = 16204
current_ts = 200.590439
current_received_ts = 200.590164
current_seq = 16205
count = 169
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.582108/16204, current 200.590439/16205: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.590439
last_received_ts = 200.590164
last_seq = 16205
current_ts = 200.598770
current_received_ts = 200.598495
current_seq = 16206
count = 170
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.590439/16205, current 200.598770/16206: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.598770
last_received_ts = 200.598495
last_seq = 16206
current_ts = 200.607101
current_received_ts = 200.606781
current_seq = 16207
count = 171
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.598770/16206, current 200.607101/16207: elapsed=8326.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.607101
last_received_ts = 200.606781
last_seq = 16207
current_ts = 200.615433
current_received_ts = 200.615173
current_seq = 16208
count = 172
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.607101/16207, current 200.615433/16208: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.615433
last_received_ts = 200.615173
last_seq = 16208
current_ts = 200.623764
current_received_ts = 200.623489
current_seq = 16209
count = 173
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.615433/16208, current 200.623764/16209: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.623764
last_received_ts = 200.623489
last_seq = 16209
current_ts = 200.632095
current_received_ts = 200.631790
current_seq = 16210
count = 174
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.623764/16209, current 200.632095/16210: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.632095
last_received_ts = 200.631790
last_seq = 16210
current_ts = 200.640411
current_received_ts = 200.640167
current_seq = 16211
count = 175
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.632095/16210, current 200.640411/16211: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.640411
last_received_ts = 200.640167
last_seq = 16211
current_ts = 200.648758
current_received_ts = 200.648483
current_seq = 16212
count = 176
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.640411/16211, current 200.648758/16212: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.648758
last_received_ts = 200.648483
last_seq = 16212
current_ts = 200.657074
current_received_ts = 200.656815
current_seq = 16213
count = 177
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.648758/16212, current 200.657074/16213: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.657074
last_received_ts = 200.656815
last_seq = 16213
current_ts = 200.665405
current_received_ts = 200.665192
current_seq = 16214
count = 178
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.657074/16213, current 200.665405/16214: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.665405
last_received_ts = 200.665192
last_seq = 16214
current_ts = 200.673737
current_received_ts = 200.673416
current_seq = 16215
count = 179
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.665405/16214, current 200.673737/16215: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.673737
last_received_ts = 200.673416
last_seq = 16215
current_ts = 200.682068
current_received_ts = 200.681763
current_seq = 16216
count = 180
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.673737/16215, current 200.682068/16216: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.682068
last_received_ts = 200.681763
last_seq = 16216
current_ts = 200.690399
current_received_ts = 200.690170
current_seq = 16217
count = 181
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.682068/16216, current 200.690399/16217: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.690399
last_received_ts = 200.690170
last_seq = 16217
current_ts = 200.698730
current_received_ts = 200.698441
current_seq = 16218
count = 182
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.690399/16217, current 200.698730/16218: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.698730
last_received_ts = 200.698441
last_seq = 16218
current_ts = 200.707062
current_received_ts = 200.706802
current_seq = 16219
count = 183
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.698730/16218, current 200.707062/16219: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.707062
last_received_ts = 200.706802
last_seq = 16219
current_ts = 200.715393
current_received_ts = 200.715164
current_seq = 16220
count = 184
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.707062/16219, current 200.715393/16220: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.715393
last_received_ts = 200.715164
last_seq = 16220
current_ts = 200.723724
current_received_ts = 200.723465
current_seq = 16221
count = 185
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.715393/16220, current 200.723724/16221: elapsed=8326.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.723724
last_received_ts = 200.723465
last_seq = 16221
current_ts = 200.732056
current_received_ts = 200.731796
current_seq = 16222
count = 186
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.723724/16221, current 200.732056/16222: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.732056
last_received_ts = 200.731796
last_seq = 16222
current_ts = 200.740387
current_received_ts = 200.740173
current_seq = 16223
count = 187
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.732056/16222, current 200.740387/16223: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.740387
last_received_ts = 200.740173
last_seq = 16223
current_ts = 200.748718
current_received_ts = 200.748459
current_seq = 16224
count = 188
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.740387/16223, current 200.748718/16224: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.748718
last_received_ts = 200.748459
last_seq = 16224
current_ts = 200.757050
current_received_ts = 200.756775
current_seq = 16225
count = 189
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.748718/16224, current 200.757050/16225: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.757050
last_received_ts = 200.756775
last_seq = 16225
current_ts = 200.765381
current_received_ts = 200.765091
current_seq = 16226
count = 190
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.757050/16225, current 200.765381/16226: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.765381
last_received_ts = 200.765091
last_seq = 16226
current_ts = 200.773712
current_received_ts = 200.773453
current_seq = 16227
count = 191
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.765381/16226, current 200.773712/16227: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.773712
last_received_ts = 200.773453
last_seq = 16227
current_ts = 200.782043
current_received_ts = 200.781723
current_seq = 16228
count = 192
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.773712/16227, current 200.782043/16228: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.782043
last_received_ts = 200.781723
last_seq = 16228
current_ts = 200.790359
current_received_ts = 200.790070
current_seq = 16229
count = 193
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.782043/16228, current 200.790359/16229: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.790359
last_received_ts = 200.790070
last_seq = 16229
current_ts = 200.798691
current_received_ts = 200.798370
current_seq = 16230
count = 194
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.790359/16229, current 200.798691/16230: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.798691
last_received_ts = 200.798370
last_seq = 16230
current_ts = 200.807022
current_received_ts = 200.806732
current_seq = 16231
count = 195
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.798691/16230, current 200.807022/16231: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.807022
last_received_ts = 200.806732
last_seq = 16231
current_ts = 200.815369
current_received_ts = 200.815079
current_seq = 16232
count = 196
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.807022/16231, current 200.815369/16232: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.815369
last_received_ts = 200.815079
last_seq = 16232
current_ts = 200.823685
current_received_ts = 200.823364
current_seq = 16233
count = 197
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.815369/16232, current 200.823685/16233: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.823685
last_received_ts = 200.823364
last_seq = 16233
current_ts = 200.832016
current_received_ts = 200.831787
current_seq = 16234
count = 198
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.823685/16233, current 200.832016/16234: elapsed=8326.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.832016
last_received_ts = 200.831787
last_seq = 16234
current_ts = 200.840347
current_received_ts = 200.840118
current_seq = 16235
count = 199
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.832016/16234, current 200.840347/16235: elapsed=8337.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.840347
last_received_ts = 200.840118
last_seq = 16235
current_ts = 200.848679
current_received_ts = 200.848434
current_seq = 16236
count = 200
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.840347/16235, current 200.848679/16236: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.848679
last_received_ts = 200.848434
last_seq = 16236
current_ts = 200.857010
current_received_ts = 200.856689
current_seq = 16237
count = 201
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.848679/16236, current 200.857010/16237: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.857010
last_received_ts = 200.856689
last_seq = 16237
current_ts = 200.865341
current_received_ts = 200.865067
current_seq = 16238
count = 202
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.857010/16237, current 200.865341/16238: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.865341
last_received_ts = 200.865067
last_seq = 16238
current_ts = 200.873672
current_received_ts = 200.873398
current_seq = 16239
count = 203
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.865341/16238, current 200.873672/16239: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.873672
last_received_ts = 200.873398
last_seq = 16239
current_ts = 200.882004
current_received_ts = 200.881699
current_seq = 16240
count = 204
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.873672/16239, current 200.882004/16240: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.882004
last_received_ts = 200.881699
last_seq = 16240
current_ts = 200.890335
current_received_ts = 200.890121
current_seq = 16241
count = 205
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.882004/16240, current 200.890335/16241: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.890335
last_received_ts = 200.890121
last_seq = 16241
current_ts = 200.898666
current_received_ts = 200.898407
current_seq = 16242
count = 206
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.890335/16241, current 200.898666/16242: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.898666
last_received_ts = 200.898407
last_seq = 16242
current_ts = 200.906982
current_received_ts = 200.906693
current_seq = 16243
count = 207
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.898666/16242, current 200.906982/16243: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.906982
last_received_ts = 200.906693
last_seq = 16243
current_ts = 200.915329
current_received_ts = 200.915039
current_seq = 16244
count = 208
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.906982/16243, current 200.915329/16244: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.915329
last_received_ts = 200.915039
last_seq = 16244
current_ts = 200.923660
current_received_ts = 200.923416
current_seq = 16245
count = 209
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.915329/16244, current 200.923660/16245: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.923660
last_received_ts = 200.923416
last_seq = 16245
current_ts = 200.931976
current_received_ts = 200.931671
current_seq = 16246
count = 210
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.923660/16245, current 200.931976/16246: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.931976
last_received_ts = 200.931671
last_seq = 16246
current_ts = 200.940323
current_received_ts = 200.940109
current_seq = 16247
count = 211
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.931976/16246, current 200.940323/16247: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.940323
last_received_ts = 200.940109
last_seq = 16247
current_ts = 200.948639
current_received_ts = 200.948395
current_seq = 16248
count = 212
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.940323/16247, current 200.948639/16248: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.948639
last_received_ts = 200.948395
last_seq = 16248
current_ts = 200.956970
current_received_ts = 200.956711
current_seq = 16249
count = 213
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.948639/16248, current 200.956970/16249: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.956970
last_received_ts = 200.956711
last_seq = 16249
current_ts = 200.965302
current_received_ts = 200.965012
current_seq = 16250
count = 214
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.956970/16249, current 200.965302/16250: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.965302
last_received_ts = 200.965012
last_seq = 16250
current_ts = 200.973633
current_received_ts = 200.973312
current_seq = 16251
count = 215
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.965302/16250, current 200.973633/16251: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.973633
last_received_ts = 200.973312
last_seq = 16251
current_ts = 200.981964
current_received_ts = 200.981735
current_seq = 16252
count = 216
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.973633/16251, current 200.981964/16252: elapsed=8333.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.981964
last_received_ts = 200.981735
last_seq = 16252
current_ts = 200.990295
current_received_ts = 200.990158
current_seq = 16253
count = 217
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.981964/16252, current 200.990295/16253: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.990295
last_received_ts = 200.990158
last_seq = 16253
current_ts = 200.998627
current_received_ts = 200.998367
current_seq = 16254
count = 218
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.990295/16253, current 200.998627/16254: elapsed=8332.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 200.998627
last_received_ts = 200.998367
last_seq = 16254
current_ts = 201.006958
current_received_ts = 201.006668
current_seq = 16255
count = 219
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 200.998627/16254, current 201.006958/16255: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.006958
last_received_ts = 201.006668
last_seq = 16255
current_ts = 201.015289
current_received_ts = 201.015152
current_seq = 16256
count = 220
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.006958/16255, current 201.015289/16256: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.015289
last_received_ts = 201.015152
last_seq = 16256
current_ts = 201.023621
current_received_ts = 201.023315
current_seq = 16257
count = 221
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.015289/16256, current 201.023621/16257: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.023621
last_received_ts = 201.023315
last_seq = 16257
current_ts = 201.031952
current_received_ts = 201.031631
current_seq = 16258
count = 222
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.023621/16257, current 201.031952/16258: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.031952
last_received_ts = 201.031631
last_seq = 16258
current_ts = 201.040283
current_received_ts = 201.039963
current_seq = 16259
count = 223
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.031952/16258, current 201.040283/16259: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.040283
last_received_ts = 201.039963
last_seq = 16259
current_ts = 201.048599
current_received_ts = 201.048279
current_seq = 16260
count = 224
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.040283/16259, current 201.048599/16260: elapsed=8329.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.048599
last_received_ts = 201.048279
last_seq = 16260
current_ts = 201.056946
current_received_ts = 201.056702
current_seq = 16261
count = 225
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.048599/16260, current 201.056946/16261: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.056946
last_received_ts = 201.056702
last_seq = 16261
current_ts = 201.065262
current_received_ts = 201.064972
current_seq = 16262
count = 226
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.056946/16261, current 201.065262/16262: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.065262
last_received_ts = 201.064972
last_seq = 16262
current_ts = 201.073593
current_received_ts = 201.073288
current_seq = 16263
count = 227
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.065262/16262, current 201.073593/16263: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.073593
last_received_ts = 201.073288
last_seq = 16263
current_ts = 201.081924
current_received_ts = 201.081650
current_seq = 16264
count = 228
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.073593/16263, current 201.081924/16264: elapsed=8335.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.081924
last_received_ts = 201.081650
last_seq = 16264
current_ts = 201.090256
current_received_ts = 201.089935
current_seq = 16265
count = 229
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.081924/16264, current 201.090256/16265: elapsed=8331.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.090256
last_received_ts = 201.089935
last_seq = 16265
current_ts = 201.098587
current_received_ts = 201.098282
current_seq = 16266
count = 230
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.090256/16265, current 201.098587/16266: elapsed=8327.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.098587
last_received_ts = 201.098282
last_seq = 16266
current_ts = 201.106918
current_received_ts = 201.106644
current_seq = 16267
count = 231
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.098587/16266, current 201.106918/16267: elapsed=8334.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.106918
last_received_ts = 201.106644
last_seq = 16267
current_ts = 201.115250
current_received_ts = 201.114944
current_seq = 16268
count = 232
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.106918/16267, current 201.115250/16268: elapsed=8330.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.115250
last_received_ts = 201.114944
last_seq = 16268
current_ts = 201.123581
current_received_ts = 201.123352
current_seq = 16269
count = 233
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.115250/16268, current 201.123581/16269: elapsed=8326.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.123581
last_received_ts = 201.123352
last_seq = 16269
current_ts = 201.131912
current_received_ts = 201.131638
current_seq = 16270
count = 234
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.123581/16269, current 201.131912/16270: elapsed=8336.0us expected=8334.9us +- 41.7us, error 0.0%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.131912
last_received_ts = 201.131638
last_seq = 16270
current_ts = 201.140244
current_received_ts = 201.139923
current_seq = 16271
count = 235
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.131912/16270, current 201.140244/16271: elapsed=8328.0us expected=8334.9us +- 41.7us, error 0.1%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.140244
last_received_ts = 201.139923
last_seq = 16271
current_ts = 201.148544
current_received_ts = 201.148315
current_seq = 16272
count = 236
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.140244/16271, current 201.148544/16272: elapsed=8307.0us expected=8334.9us +- 41.7us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 201.148544
last_received_ts = 201.148315
last_seq = 16272
current_ts = 201.156830
current_received_ts = 201.156525
current_seq = 16273
count = 237
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 201.148544/16272, current 201.156830/16273: elapsed=8277.0us expected=8334.9us +- 41.7us, error 0.7%
(kms_flip:2430) DEBUG: inconsistent flip ts/seq: last 201.148544/16272, current 201.156830/16273: elapsed=8277.0us expected=8334.9us
(kms_flip:2430) DEBUG: expected 80207, counted 237, encoder type 2
(kms_flip:2430) DEBUG: dropped frames, expected 80207, counted 237, encoder type 2
(kms_flip:2430) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2430) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2430) igt_core-INFO: Stack trace:
(kms_flip:2430) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2430) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2430) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2430) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2430) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2430) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2430) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2430) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (5.536s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2430) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2430) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.196487
last_received_ts = 211.196228
last_seq = 978
current_ts = 211.204803
current_received_ts = 211.204575
current_seq = 979
count = 782
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.196487/978, current 211.204803/979: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.204803
last_received_ts = 211.204575
last_seq = 979
current_ts = 211.213120
current_received_ts = 211.212921
current_seq = 980
count = 783
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.204803/979, current 211.213120/980: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.213120
last_received_ts = 211.212921
last_seq = 980
current_ts = 211.221436
current_received_ts = 211.221146
current_seq = 981
count = 784
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.213120/980, current 211.221436/981: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.221436
last_received_ts = 211.221146
last_seq = 981
current_ts = 211.229752
current_received_ts = 211.229431
current_seq = 982
count = 785
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.221436/981, current 211.229752/982: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.229752
last_received_ts = 211.229431
last_seq = 982
current_ts = 211.238068
current_received_ts = 211.237762
current_seq = 983
count = 786
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.229752/982, current 211.238068/983: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.238068
last_received_ts = 211.237762
last_seq = 983
current_ts = 211.246384
current_received_ts = 211.246170
current_seq = 984
count = 787
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.238068/983, current 211.246384/984: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.246384
last_received_ts = 211.246170
last_seq = 984
current_ts = 211.254700
current_received_ts = 211.254501
current_seq = 985
count = 788
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.246384/984, current 211.254700/985: elapsed=8313.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.254700
last_received_ts = 211.254501
last_seq = 985
current_ts = 211.263016
current_received_ts = 211.262802
current_seq = 986
count = 789
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.254700/985, current 211.263016/986: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.263016
last_received_ts = 211.262802
last_seq = 986
current_ts = 211.271332
current_received_ts = 211.271042
current_seq = 987
count = 790
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.263016/986, current 211.271332/987: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.271332
last_received_ts = 211.271042
last_seq = 987
current_ts = 211.279648
current_received_ts = 211.279297
current_seq = 988
count = 791
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.271332/987, current 211.279648/988: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.279648
last_received_ts = 211.279297
last_seq = 988
current_ts = 211.287964
current_received_ts = 211.287704
current_seq = 989
count = 792
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.279648/988, current 211.287964/989: elapsed=8313.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.287964
last_received_ts = 211.287704
last_seq = 989
current_ts = 211.296280
current_received_ts = 211.295990
current_seq = 990
count = 793
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.287964/989, current 211.296280/990: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.296280
last_received_ts = 211.295990
last_seq = 990
current_ts = 211.304596
current_received_ts = 211.304367
current_seq = 991
count = 794
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.296280/990, current 211.304596/991: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.304596
last_received_ts = 211.304367
last_seq = 991
current_ts = 211.312927
current_received_ts = 211.312607
current_seq = 992
count = 795
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.304596/991, current 211.312927/992: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.312927
last_received_ts = 211.312607
last_seq = 992
current_ts = 211.321228
current_received_ts = 211.320969
current_seq = 993
count = 796
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.312927/992, current 211.321228/993: elapsed=8311.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.321228
last_received_ts = 211.320969
last_seq = 993
current_ts = 211.329544
current_received_ts = 211.329254
current_seq = 994
count = 797
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.321228/993, current 211.329544/994: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.329544
last_received_ts = 211.329254
last_seq = 994
current_ts = 211.337875
current_received_ts = 211.337585
current_seq = 995
count = 798
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.329544/994, current 211.337875/995: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.337875
last_received_ts = 211.337585
last_seq = 995
current_ts = 211.346176
current_received_ts = 211.345871
current_seq = 996
count = 799
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.337875/995, current 211.346176/996: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.346176
last_received_ts = 211.345871
last_seq = 996
current_ts = 211.354492
current_received_ts = 211.354263
current_seq = 997
count = 800
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.346176/996, current 211.354492/997: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.354492
last_received_ts = 211.354263
last_seq = 997
current_ts = 211.362823
current_received_ts = 211.362595
current_seq = 998
count = 801
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.354492/997, current 211.362823/998: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.362823
last_received_ts = 211.362595
last_seq = 998
current_ts = 211.371140
current_received_ts = 211.370941
current_seq = 999
count = 802
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.362823/998, current 211.371140/999: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.371140
last_received_ts = 211.370941
last_seq = 999
current_ts = 211.379456
current_received_ts = 211.379150
current_seq = 1000
count = 803
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.371140/999, current 211.379456/1000: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.379456
last_received_ts = 211.379150
last_seq = 1000
current_ts = 211.387772
current_received_ts = 211.387527
current_seq = 1001
count = 804
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.379456/1000, current 211.387772/1001: elapsed=8311.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.387772
last_received_ts = 211.387527
last_seq = 1001
current_ts = 211.396088
current_received_ts = 211.395905
current_seq = 1002
count = 805
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.387772/1001, current 211.396088/1002: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.396088
last_received_ts = 211.395905
last_seq = 1002
current_ts = 211.404404
current_received_ts = 211.404129
current_seq = 1003
count = 806
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.396088/1002, current 211.404404/1003: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.404404
last_received_ts = 211.404129
last_seq = 1003
current_ts = 211.412720
current_received_ts = 211.412460
current_seq = 1004
count = 807
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.404404/1003, current 211.412720/1004: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.412720
last_received_ts = 211.412460
last_seq = 1004
current_ts = 211.421036
current_received_ts = 211.420731
current_seq = 1005
count = 808
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.412720/1004, current 211.421036/1005: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.421036
last_received_ts = 211.420731
last_seq = 1005
current_ts = 211.429352
current_received_ts = 211.429092
current_seq = 1006
count = 809
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.421036/1005, current 211.429352/1006: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.429352
last_received_ts = 211.429092
last_seq = 1006
current_ts = 211.437668
current_received_ts = 211.437424
current_seq = 1007
count = 810
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.429352/1006, current 211.437668/1007: elapsed=8320.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.437668
last_received_ts = 211.437424
last_seq = 1007
current_ts = 211.445984
current_received_ts = 211.445679
current_seq = 1008
count = 811
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.437668/1007, current 211.445984/1008: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.445984
last_received_ts = 211.445679
last_seq = 1008
current_ts = 211.454300
current_received_ts = 211.454056
current_seq = 1009
count = 812
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.445984/1008, current 211.454300/1009: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.454300
last_received_ts = 211.454056
last_seq = 1009
current_ts = 211.462616
current_received_ts = 211.462387
current_seq = 1010
count = 813
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.454300/1009, current 211.462616/1010: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.462616
last_received_ts = 211.462387
last_seq = 1010
current_ts = 211.470932
current_received_ts = 211.470627
current_seq = 1011
count = 814
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.462616/1010, current 211.470932/1011: elapsed=8320.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.470932
last_received_ts = 211.470627
last_seq = 1011
current_ts = 211.479248
current_received_ts = 211.479004
current_seq = 1012
count = 815
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.470932/1011, current 211.479248/1012: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.479248
last_received_ts = 211.479004
last_seq = 1012
current_ts = 211.487564
current_received_ts = 211.487305
current_seq = 1013
count = 816
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.479248/1012, current 211.487564/1013: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.487564
last_received_ts = 211.487305
last_seq = 1013
current_ts = 211.495880
current_received_ts = 211.495590
current_seq = 1014
count = 817
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.487564/1013, current 211.495880/1014: elapsed=8320.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.495880
last_received_ts = 211.495590
last_seq = 1014
current_ts = 211.504211
current_received_ts = 211.504044
current_seq = 1015
count = 818
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.495880/1014, current 211.504211/1015: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.504211
last_received_ts = 211.504044
last_seq = 1015
current_ts = 211.512527
current_received_ts = 211.512253
current_seq = 1016
count = 819
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.504211/1015, current 211.512527/1016: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.512527
last_received_ts = 211.512253
last_seq = 1016
current_ts = 211.520844
current_received_ts = 211.520584
current_seq = 1017
count = 820
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.512527/1016, current 211.520844/1017: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.520844
last_received_ts = 211.520584
last_seq = 1017
current_ts = 211.529160
current_received_ts = 211.528946
current_seq = 1018
count = 821
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.520844/1017, current 211.529160/1018: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.529160
last_received_ts = 211.528946
last_seq = 1018
current_ts = 211.537476
current_received_ts = 211.537231
current_seq = 1019
count = 822
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.529160/1018, current 211.537476/1019: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.537476
last_received_ts = 211.537231
last_seq = 1019
current_ts = 211.545792
current_received_ts = 211.545471
current_seq = 1020
count = 823
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.537476/1019, current 211.545792/1020: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.545792
last_received_ts = 211.545471
last_seq = 1020
current_ts = 211.554108
current_received_ts = 211.553833
current_seq = 1021
count = 824
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.545792/1020, current 211.554108/1021: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.554108
last_received_ts = 211.553833
last_seq = 1021
current_ts = 211.562424
current_received_ts = 211.562149
current_seq = 1022
count = 825
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.554108/1021, current 211.562424/1022: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.562424
last_received_ts = 211.562149
last_seq = 1022
current_ts = 211.570740
current_received_ts = 211.570465
current_seq = 1023
count = 826
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.562424/1022, current 211.570740/1023: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.570740
last_received_ts = 211.570465
last_seq = 1023
current_ts = 211.579056
current_received_ts = 211.578751
current_seq = 1024
count = 827
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.570740/1023, current 211.579056/1024: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.579056
last_received_ts = 211.578751
last_seq = 1024
current_ts = 211.587372
current_received_ts = 211.587128
current_seq = 1025
count = 828
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.579056/1024, current 211.587372/1025: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.587372
last_received_ts = 211.587128
last_seq = 1025
current_ts = 211.595688
current_received_ts = 211.595428
current_seq = 1026
count = 829
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.587372/1025, current 211.595688/1026: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.595688
last_received_ts = 211.595428
last_seq = 1026
current_ts = 211.604004
current_received_ts = 211.603714
current_seq = 1027
count = 830
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.595688/1026, current 211.604004/1027: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.604004
last_received_ts = 211.603714
last_seq = 1027
current_ts = 211.612320
current_received_ts = 211.612061
current_seq = 1028
count = 831
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.604004/1027, current 211.612320/1028: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.612320
last_received_ts = 211.612061
last_seq = 1028
current_ts = 211.620636
current_received_ts = 211.620331
current_seq = 1029
count = 832
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.612320/1028, current 211.620636/1029: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.620636
last_received_ts = 211.620331
last_seq = 1029
current_ts = 211.628952
current_received_ts = 211.628708
current_seq = 1030
count = 833
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.620636/1029, current 211.628952/1030: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.628952
last_received_ts = 211.628708
last_seq = 1030
current_ts = 211.637268
current_received_ts = 211.636963
current_seq = 1031
count = 834
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.628952/1030, current 211.637268/1031: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.637268
last_received_ts = 211.636963
last_seq = 1031
current_ts = 211.645584
current_received_ts = 211.645340
current_seq = 1032
count = 835
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.637268/1031, current 211.645584/1032: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.645584
last_received_ts = 211.645340
last_seq = 1032
current_ts = 211.653915
current_received_ts = 211.653656
current_seq = 1033
count = 836
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.645584/1032, current 211.653915/1033: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.653915
last_received_ts = 211.653656
last_seq = 1033
current_ts = 211.662216
current_received_ts = 211.662064
current_seq = 1034
count = 837
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.653915/1033, current 211.662216/1034: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.662216
last_received_ts = 211.662064
last_seq = 1034
current_ts = 211.670532
current_received_ts = 211.670303
current_seq = 1035
count = 838
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.662216/1034, current 211.670532/1035: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.670532
last_received_ts = 211.670303
last_seq = 1035
current_ts = 211.678848
current_received_ts = 211.678589
current_seq = 1036
count = 839
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.670532/1035, current 211.678848/1036: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.678848
last_received_ts = 211.678589
last_seq = 1036
current_ts = 211.687164
current_received_ts = 211.686890
current_seq = 1037
count = 840
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.678848/1036, current 211.687164/1037: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.687164
last_received_ts = 211.686890
last_seq = 1037
current_ts = 211.695496
current_received_ts = 211.695251
current_seq = 1038
count = 841
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.687164/1037, current 211.695496/1038: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.695496
last_received_ts = 211.695251
last_seq = 1038
current_ts = 211.703812
current_received_ts = 211.703552
current_seq = 1039
count = 842
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.695496/1038, current 211.703812/1039: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.703812
last_received_ts = 211.703552
last_seq = 1039
current_ts = 211.712112
current_received_ts = 211.711914
current_seq = 1040
count = 843
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.703812/1039, current 211.712112/1040: elapsed=8313.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.712112
last_received_ts = 211.711914
last_seq = 1040
current_ts = 211.720444
current_received_ts = 211.720169
current_seq = 1041
count = 844
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.712112/1040, current 211.720444/1041: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.720444
last_received_ts = 211.720169
last_seq = 1041
current_ts = 211.728760
current_received_ts = 211.728531
current_seq = 1042
count = 845
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.720444/1041, current 211.728760/1042: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.728760
last_received_ts = 211.728531
last_seq = 1042
current_ts = 211.737076
current_received_ts = 211.736801
current_seq = 1043
count = 846
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.728760/1042, current 211.737076/1043: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.737076
last_received_ts = 211.736801
last_seq = 1043
current_ts = 211.745392
current_received_ts = 211.745132
current_seq = 1044
count = 847
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.737076/1043, current 211.745392/1044: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.745392
last_received_ts = 211.745132
last_seq = 1044
current_ts = 211.753708
current_received_ts = 211.753464
current_seq = 1045
count = 848
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.745392/1044, current 211.753708/1045: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.753708
last_received_ts = 211.753464
last_seq = 1045
current_ts = 211.762024
current_received_ts = 211.761703
current_seq = 1046
count = 849
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.753708/1045, current 211.762024/1046: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.762024
last_received_ts = 211.761703
last_seq = 1046
current_ts = 211.770340
current_received_ts = 211.770111
current_seq = 1047
count = 850
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.762024/1046, current 211.770340/1047: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.770340
last_received_ts = 211.770111
last_seq = 1047
current_ts = 211.778656
current_received_ts = 211.778381
current_seq = 1048
count = 851
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.770340/1047, current 211.778656/1048: elapsed=8322.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.778656
last_received_ts = 211.778381
last_seq = 1048
current_ts = 211.786972
current_received_ts = 211.786697
current_seq = 1049
count = 852
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.778656/1048, current 211.786972/1049: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.786972
last_received_ts = 211.786697
last_seq = 1049
current_ts = 211.795288
current_received_ts = 211.795029
current_seq = 1050
count = 853
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.786972/1049, current 211.795288/1050: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.795288
last_received_ts = 211.795029
last_seq = 1050
current_ts = 211.803604
current_received_ts = 211.803345
current_seq = 1051
count = 854
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.795288/1050, current 211.803604/1051: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.803604
last_received_ts = 211.803345
last_seq = 1051
current_ts = 211.811920
current_received_ts = 211.811646
current_seq = 1052
count = 855
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.803604/1051, current 211.811920/1052: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.811920
last_received_ts = 211.811646
last_seq = 1052
current_ts = 211.820236
current_received_ts = 211.820114
current_seq = 1053
count = 856
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.811920/1052, current 211.820236/1053: elapsed=8322.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.820236
last_received_ts = 211.820114
last_seq = 1053
current_ts = 211.828552
current_received_ts = 211.828293
current_seq = 1054
count = 857
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.820236/1053, current 211.828552/1054: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.828552
last_received_ts = 211.828293
last_seq = 1054
current_ts = 211.836868
current_received_ts = 211.836609
current_seq = 1055
count = 858
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.828552/1054, current 211.836868/1055: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.836868
last_received_ts = 211.836609
last_seq = 1055
current_ts = 211.845184
current_received_ts = 211.844940
current_seq = 1056
count = 859
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.836868/1055, current 211.845184/1056: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.845184
last_received_ts = 211.844940
last_seq = 1056
current_ts = 211.853516
current_received_ts = 211.853195
current_seq = 1057
count = 860
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.845184/1056, current 211.853516/1057: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.853516
last_received_ts = 211.853195
last_seq = 1057
current_ts = 211.861816
current_received_ts = 211.861511
current_seq = 1058
count = 861
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.853516/1057, current 211.861816/1058: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.861816
last_received_ts = 211.861511
last_seq = 1058
current_ts = 211.870132
current_received_ts = 211.869873
current_seq = 1059
count = 862
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.861816/1058, current 211.870132/1059: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.870132
last_received_ts = 211.869873
last_seq = 1059
current_ts = 211.878448
current_received_ts = 211.878220
current_seq = 1060
count = 863
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.870132/1059, current 211.878448/1060: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.878448
last_received_ts = 211.878220
last_seq = 1060
current_ts = 211.886780
current_received_ts = 211.886581
current_seq = 1061
count = 864
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.878448/1060, current 211.886780/1061: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.886780
last_received_ts = 211.886581
last_seq = 1061
current_ts = 211.895096
current_received_ts = 211.894775
current_seq = 1062
count = 865
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.886780/1061, current 211.895096/1062: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.895096
last_received_ts = 211.894775
last_seq = 1062
current_ts = 211.903412
current_received_ts = 211.903183
current_seq = 1063
count = 866
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.895096/1062, current 211.903412/1063: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.903412
last_received_ts = 211.903183
last_seq = 1063
current_ts = 211.911728
current_received_ts = 211.911453
current_seq = 1064
count = 867
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.903412/1063, current 211.911728/1064: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.911728
last_received_ts = 211.911453
last_seq = 1064
current_ts = 211.920044
current_received_ts = 211.919724
current_seq = 1065
count = 868
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.911728/1064, current 211.920044/1065: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.920044
last_received_ts = 211.919724
last_seq = 1065
current_ts = 211.928360
current_received_ts = 211.928177
current_seq = 1066
count = 869
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.920044/1065, current 211.928360/1066: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.928360
last_received_ts = 211.928177
last_seq = 1066
current_ts = 211.936676
current_received_ts = 211.936386
current_seq = 1067
count = 870
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.928360/1066, current 211.936676/1067: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.936676
last_received_ts = 211.936386
last_seq = 1067
current_ts = 211.944992
current_received_ts = 211.944702
current_seq = 1068
count = 871
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.936676/1067, current 211.944992/1068: elapsed=8323.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.944992
last_received_ts = 211.944702
last_seq = 1068
current_ts = 211.953308
current_received_ts = 211.953049
current_seq = 1069
count = 872
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.944992/1068, current 211.953308/1069: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.953308
last_received_ts = 211.953049
last_seq = 1069
current_ts = 211.961624
current_received_ts = 211.961304
current_seq = 1070
count = 873
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.953308/1069, current 211.961624/1070: elapsed=8313.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.961624
last_received_ts = 211.961304
last_seq = 1070
current_ts = 211.969940
current_received_ts = 211.969711
current_seq = 1071
count = 874
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.961624/1070, current 211.969940/1071: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.969940
last_received_ts = 211.969711
last_seq = 1071
current_ts = 211.978256
current_received_ts = 211.977951
current_seq = 1072
count = 875
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.969940/1071, current 211.978256/1072: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.978256
last_received_ts = 211.977951
last_seq = 1072
current_ts = 211.986572
current_received_ts = 211.986282
current_seq = 1073
count = 876
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.978256/1072, current 211.986572/1073: elapsed=8312.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.986572
last_received_ts = 211.986282
last_seq = 1073
current_ts = 211.994888
current_received_ts = 211.994690
current_seq = 1074
count = 877
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.986572/1073, current 211.994888/1074: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 211.994888
last_received_ts = 211.994690
last_seq = 1074
current_ts = 212.003204
current_received_ts = 212.003052
current_seq = 1075
count = 878
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 211.994888/1074, current 212.003204/1075: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.003204
last_received_ts = 212.003052
last_seq = 1075
current_ts = 212.011520
current_received_ts = 212.011292
current_seq = 1076
count = 879
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.003204/1075, current 212.011520/1076: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.011520
last_received_ts = 212.011292
last_seq = 1076
current_ts = 212.019836
current_received_ts = 212.019562
current_seq = 1077
count = 880
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.011520/1076, current 212.019836/1077: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.019836
last_received_ts = 212.019562
last_seq = 1077
current_ts = 212.028152
current_received_ts = 212.027847
current_seq = 1078
count = 881
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.019836/1077, current 212.028152/1078: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.028152
last_received_ts = 212.027847
last_seq = 1078
current_ts = 212.036484
current_received_ts = 212.036255
current_seq = 1079
count = 882
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.028152/1078, current 212.036484/1079: elapsed=8323.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.036484
last_received_ts = 212.036255
last_seq = 1079
current_ts = 212.044785
current_received_ts = 212.044571
current_seq = 1080
count = 883
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.036484/1079, current 212.044785/1080: elapsed=8310.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.044785
last_received_ts = 212.044571
last_seq = 1080
current_ts = 212.053116
current_received_ts = 212.052872
current_seq = 1081
count = 884
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.044785/1080, current 212.053116/1081: elapsed=8320.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.053116
last_received_ts = 212.052872
last_seq = 1081
current_ts = 212.061432
current_received_ts = 212.061172
current_seq = 1082
count = 885
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.053116/1081, current 212.061432/1082: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.061432
last_received_ts = 212.061172
last_seq = 1082
current_ts = 212.069748
current_received_ts = 212.069443
current_seq = 1083
count = 886
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.061432/1082, current 212.069748/1083: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.069748
last_received_ts = 212.069443
last_seq = 1083
current_ts = 212.078049
current_received_ts = 212.077866
current_seq = 1084
count = 887
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.069748/1083, current 212.078049/1084: elapsed=8314.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.078049
last_received_ts = 212.077866
last_seq = 1084
current_ts = 212.086380
current_received_ts = 212.086075
current_seq = 1085
count = 888
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.078049/1084, current 212.086380/1085: elapsed=8322.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.086380
last_received_ts = 212.086075
last_seq = 1085
current_ts = 212.094696
current_received_ts = 212.094528
current_seq = 1086
count = 889
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.086380/1085, current 212.094696/1086: elapsed=8311.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.094696
last_received_ts = 212.094528
last_seq = 1086
current_ts = 212.103012
current_received_ts = 212.102692
current_seq = 1087
count = 890
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.094696/1086, current 212.103012/1087: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.103012
last_received_ts = 212.102692
last_seq = 1087
current_ts = 212.111328
current_received_ts = 212.110992
current_seq = 1088
count = 891
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.103012/1087, current 212.111328/1088: elapsed=8320.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.111328
last_received_ts = 212.110992
last_seq = 1088
current_ts = 212.119644
current_received_ts = 212.119339
current_seq = 1089
count = 892
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.111328/1088, current 212.119644/1089: elapsed=8316.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.119644
last_received_ts = 212.119339
last_seq = 1089
current_ts = 212.127960
current_received_ts = 212.127640
current_seq = 1090
count = 893
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.119644/1089, current 212.127960/1090: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.127960
last_received_ts = 212.127640
last_seq = 1090
current_ts = 212.136276
current_received_ts = 212.136078
current_seq = 1091
count = 894
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.127960/1090, current 212.136276/1091: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.136276
last_received_ts = 212.136078
last_seq = 1091
current_ts = 212.144592
current_received_ts = 212.144348
current_seq = 1092
count = 895
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.136276/1091, current 212.144592/1092: elapsed=8315.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.144592
last_received_ts = 212.144348
last_seq = 1092
current_ts = 212.152908
current_received_ts = 212.152679
current_seq = 1093
count = 896
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.144592/1092, current 212.152908/1093: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.152908
last_received_ts = 212.152679
last_seq = 1093
current_ts = 212.161224
current_received_ts = 212.160919
current_seq = 1094
count = 897
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.152908/1093, current 212.161224/1094: elapsed=8317.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.161224
last_received_ts = 212.160919
last_seq = 1094
current_ts = 212.169540
current_received_ts = 212.169312
current_seq = 1095
count = 898
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.161224/1094, current 212.169540/1095: elapsed=8321.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.169540
last_received_ts = 212.169312
last_seq = 1095
current_ts = 212.177872
current_received_ts = 212.177658
current_seq = 1096
count = 899
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.169540/1095, current 212.177872/1096: elapsed=8322.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.177872
last_received_ts = 212.177658
last_seq = 1096
current_ts = 212.186188
current_received_ts = 212.185989
current_seq = 1097
count = 900
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.177872/1096, current 212.186188/1097: elapsed=8318.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.186188
last_received_ts = 212.185989
last_seq = 1097
current_ts = 212.194504
current_received_ts = 212.194260
current_seq = 1098
count = 901
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.186188/1097, current 212.194504/1098: elapsed=8313.0us expected=8295.6us +- 41.5us, error 0.2%
(kms_flip:2430) DEBUG: name = flip
last_ts = 212.194504
last_received_ts = 212.194260
last_seq = 1098
current_ts = 212.202820
current_received_ts = 212.202515
current_seq = 1099
count = 902
seq_step = 1
(kms_flip:2430) DEBUG: flip ts/seq: last 212.194504/1098, current 212.202820/1099: elapsed=8319.0us expected=8295.6us +- 41.5us, error 0.3%
(kms_flip:2430) DEBUG: expected 904, counted 903, encoder type 2
(kms_flip:2430) DEBUG: dropped frames, expected 904, counted 903, encoder type 2
(kms_flip:2430) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2430) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2430) igt_core-INFO: Stack trace:
(kms_flip:2430) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2430) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2430) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2430) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2430) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2430) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2430) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2430) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (11.020s)
Starting dynamic subtest: C-HDMI-A1
Dynamic subtest C-HDMI-A1: SUCCESS (7.816s)
Starting dynamic subtest: D-HDMI-A1
Dynamic subtest D-HDMI-A1: SUCCESS (7.811s)
Subtest plain-flip-ts-check: FAIL (32.194s)