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

shard-rkl-7

IGT-Version: 1.30-g0a4beb5fb (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16231-g3ccfd8016ad8+ x86_64)

Using IGT_SRANDOM=1741241760 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 19136.1us +- 8.767us accuracy 0.14%
vblank interval differs from modeline! expected 18973.8us, measured 19136us +- 8.767us, difference 162.3us (18.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (9.031s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 19021.6us +- 8.334us accuracy 0.13%
vblank interval differs from modeline! expected 18973.8us, measured 19022us +- 8.334us, difference 47.8us (5.7 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (18.658s)
Subtest plain-flip-ts-check: FAIL (27.694s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2058) DEBUG: flip ts/seq: last 64.489006/591, current 64.508087/592: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.508087
last_received_ts = 64.507370
last_seq = 592
current_ts = 64.527168
current_received_ts = 64.526459
current_seq = 593
count = 159
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.508087/592, current 64.527168/593: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.527168
last_received_ts = 64.526459
last_seq = 593
current_ts = 64.546257
current_received_ts = 64.545540
current_seq = 594
count = 160
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.527168/593, current 64.546257/594: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.546257
last_received_ts = 64.545540
last_seq = 594
current_ts = 64.565338
current_received_ts = 64.564621
current_seq = 595
count = 161
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.546257/594, current 64.565338/595: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.565338
last_received_ts = 64.564621
last_seq = 595
current_ts = 64.584419
current_received_ts = 64.583702
current_seq = 596
count = 162
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.565338/595, current 64.584419/596: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.584419
last_received_ts = 64.583702
last_seq = 596
current_ts = 64.603500
current_received_ts = 64.602783
current_seq = 597
count = 163
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.584419/596, current 64.603500/597: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.603500
last_received_ts = 64.602783
last_seq = 597
current_ts = 64.622581
current_received_ts = 64.621864
current_seq = 598
count = 164
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.603500/597, current 64.622581/598: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.622581
last_received_ts = 64.621864
last_seq = 598
current_ts = 64.641663
current_received_ts = 64.640953
current_seq = 599
count = 165
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.622581/598, current 64.641663/599: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.641663
last_received_ts = 64.640953
last_seq = 599
current_ts = 64.660751
current_received_ts = 64.660057
current_seq = 600
count = 166
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.641663/599, current 64.660751/600: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.660751
last_received_ts = 64.660057
last_seq = 600
current_ts = 64.679832
current_received_ts = 64.679115
current_seq = 601
count = 167
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.660751/600, current 64.679832/601: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.679832
last_received_ts = 64.679115
last_seq = 601
current_ts = 64.698914
current_received_ts = 64.698196
current_seq = 602
count = 168
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.679832/601, current 64.698914/602: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.698914
last_received_ts = 64.698196
last_seq = 602
current_ts = 64.717995
current_received_ts = 64.717278
current_seq = 603
count = 169
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.698914/602, current 64.717995/603: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.717995
last_received_ts = 64.717278
last_seq = 603
current_ts = 64.737076
current_received_ts = 64.736366
current_seq = 604
count = 170
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.717995/603, current 64.737076/604: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.737076
last_received_ts = 64.736366
last_seq = 604
current_ts = 64.756157
current_received_ts = 64.755447
current_seq = 605
count = 171
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.737076/604, current 64.756157/605: elapsed=19081.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.756157
last_received_ts = 64.755447
last_seq = 605
current_ts = 64.775246
current_received_ts = 64.774529
current_seq = 606
count = 172
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.756157/605, current 64.775246/606: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.775246
last_received_ts = 64.774529
last_seq = 606
current_ts = 64.794327
current_received_ts = 64.793610
current_seq = 607
count = 173
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.775246/606, current 64.794327/607: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.794327
last_received_ts = 64.793610
last_seq = 607
current_ts = 64.813408
current_received_ts = 64.812691
current_seq = 608
count = 174
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.794327/607, current 64.813408/608: elapsed=19083.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.813408
last_received_ts = 64.812691
last_seq = 608
current_ts = 64.832474
current_received_ts = 64.831779
current_seq = 609
count = 175
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.813408/608, current 64.832474/609: elapsed=19066.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.832474
last_received_ts = 64.831779
last_seq = 609
current_ts = 64.851570
current_received_ts = 64.850853
current_seq = 610
count = 176
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.832474/609, current 64.851570/610: elapsed=19096.0us expected=19136.1us +- 95.7us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.851570
last_received_ts = 64.850853
last_seq = 610
current_ts = 64.870644
current_received_ts = 64.869926
current_seq = 611
count = 177
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.851570/610, current 64.870644/611: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.870644
last_received_ts = 64.869926
last_seq = 611
current_ts = 64.889709
current_received_ts = 64.888992
current_seq = 612
count = 178
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.870644/611, current 64.889709/612: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.889709
last_received_ts = 64.888992
last_seq = 612
current_ts = 64.908768
current_received_ts = 64.908081
current_seq = 613
count = 179
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.889709/612, current 64.908768/613: elapsed=19059.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.908768
last_received_ts = 64.908081
last_seq = 613
current_ts = 64.927849
current_received_ts = 64.927132
current_seq = 614
count = 180
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.908768/613, current 64.927849/614: elapsed=19079.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.927849
last_received_ts = 64.927132
last_seq = 614
current_ts = 64.946915
current_received_ts = 64.946198
current_seq = 615
count = 181
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.927849/614, current 64.946915/615: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.946915
last_received_ts = 64.946198
last_seq = 615
current_ts = 64.965988
current_received_ts = 64.965271
current_seq = 616
count = 182
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.946915/615, current 64.965988/616: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.965988
last_received_ts = 64.965271
last_seq = 616
current_ts = 64.985054
current_received_ts = 64.984337
current_seq = 617
count = 183
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.965988/616, current 64.985054/617: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 64.985054
last_received_ts = 64.984337
last_seq = 617
current_ts = 65.004120
current_received_ts = 65.003410
current_seq = 618
count = 184
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 64.985054/617, current 65.004120/618: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.004120
last_received_ts = 65.003410
last_seq = 618
current_ts = 65.023193
current_received_ts = 65.022476
current_seq = 619
count = 185
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.004120/618, current 65.023193/619: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.023193
last_received_ts = 65.022476
last_seq = 619
current_ts = 65.042259
current_received_ts = 65.041542
current_seq = 620
count = 186
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.023193/619, current 65.042259/620: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.042259
last_received_ts = 65.041542
last_seq = 620
current_ts = 65.061333
current_received_ts = 65.060616
current_seq = 621
count = 187
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.042259/620, current 65.061333/621: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.061333
last_received_ts = 65.060616
last_seq = 621
current_ts = 65.080399
current_received_ts = 65.079681
current_seq = 622
count = 188
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.061333/621, current 65.080399/622: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.080399
last_received_ts = 65.079681
last_seq = 622
current_ts = 65.099464
current_received_ts = 65.098755
current_seq = 623
count = 189
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.080399/622, current 65.099464/623: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.099464
last_received_ts = 65.098755
last_seq = 623
current_ts = 65.118538
current_received_ts = 65.117821
current_seq = 624
count = 190
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.099464/623, current 65.118538/624: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.118538
last_received_ts = 65.117821
last_seq = 624
current_ts = 65.137604
current_received_ts = 65.136887
current_seq = 625
count = 191
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.118538/624, current 65.137604/625: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.137604
last_received_ts = 65.136887
last_seq = 625
current_ts = 65.156677
current_received_ts = 65.155960
current_seq = 626
count = 192
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.137604/625, current 65.156677/626: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.156677
last_received_ts = 65.155960
last_seq = 626
current_ts = 65.175743
current_received_ts = 65.175049
current_seq = 627
count = 193
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.156677/626, current 65.175743/627: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.175743
last_received_ts = 65.175049
last_seq = 627
current_ts = 65.194809
current_received_ts = 65.194099
current_seq = 628
count = 194
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.175743/627, current 65.194809/628: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.194809
last_received_ts = 65.194099
last_seq = 628
current_ts = 65.213882
current_received_ts = 65.213165
current_seq = 629
count = 195
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.194809/628, current 65.213882/629: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.213882
last_received_ts = 65.213165
last_seq = 629
current_ts = 65.232948
current_received_ts = 65.232231
current_seq = 630
count = 196
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.213882/629, current 65.232948/630: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.232948
last_received_ts = 65.232231
last_seq = 630
current_ts = 65.252022
current_received_ts = 65.251305
current_seq = 631
count = 197
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.232948/630, current 65.252022/631: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.252022
last_received_ts = 65.251305
last_seq = 631
current_ts = 65.271088
current_received_ts = 65.270370
current_seq = 632
count = 198
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.252022/631, current 65.271088/632: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.271088
last_received_ts = 65.270370
last_seq = 632
current_ts = 65.290154
current_received_ts = 65.289436
current_seq = 633
count = 199
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.271088/632, current 65.290154/633: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.290154
last_received_ts = 65.289436
last_seq = 633
current_ts = 65.309227
current_received_ts = 65.308510
current_seq = 634
count = 200
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.290154/633, current 65.309227/634: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.309227
last_received_ts = 65.308510
last_seq = 634
current_ts = 65.328278
current_received_ts = 65.327583
current_seq = 635
count = 201
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.309227/634, current 65.328278/635: elapsed=19053.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.328278
last_received_ts = 65.327583
last_seq = 635
current_ts = 65.347366
current_received_ts = 65.346649
current_seq = 636
count = 202
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.328278/635, current 65.347366/636: elapsed=19084.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.347366
last_received_ts = 65.346649
last_seq = 636
current_ts = 65.366432
current_received_ts = 65.365715
current_seq = 637
count = 203
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.347366/636, current 65.366432/637: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.366432
last_received_ts = 65.365715
last_seq = 637
current_ts = 65.385498
current_received_ts = 65.384789
current_seq = 638
count = 204
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.366432/637, current 65.385498/638: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.385498
last_received_ts = 65.384789
last_seq = 638
current_ts = 65.404572
current_received_ts = 65.403854
current_seq = 639
count = 205
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.385498/638, current 65.404572/639: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.404572
last_received_ts = 65.403854
last_seq = 639
current_ts = 65.423637
current_received_ts = 65.422920
current_seq = 640
count = 206
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.404572/639, current 65.423637/640: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.423637
last_received_ts = 65.422920
last_seq = 640
current_ts = 65.442711
current_received_ts = 65.441994
current_seq = 641
count = 207
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.423637/640, current 65.442711/641: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.442711
last_received_ts = 65.441994
last_seq = 641
current_ts = 65.461761
current_received_ts = 65.461075
current_seq = 642
count = 208
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.442711/641, current 65.461761/642: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.461761
last_received_ts = 65.461075
last_seq = 642
current_ts = 65.480843
current_received_ts = 65.480133
current_seq = 643
count = 209
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.461761/642, current 65.480843/643: elapsed=19082.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.480843
last_received_ts = 65.480133
last_seq = 643
current_ts = 65.499916
current_received_ts = 65.499199
current_seq = 644
count = 210
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.480843/643, current 65.499916/644: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.499916
last_received_ts = 65.499199
last_seq = 644
current_ts = 65.518982
current_received_ts = 65.518272
current_seq = 645
count = 211
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.499916/644, current 65.518982/645: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.518982
last_received_ts = 65.518272
last_seq = 645
current_ts = 65.538055
current_received_ts = 65.537338
current_seq = 646
count = 212
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.518982/645, current 65.538055/646: elapsed=19070.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.538055
last_received_ts = 65.537338
last_seq = 646
current_ts = 65.557121
current_received_ts = 65.556412
current_seq = 647
count = 213
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.538055/646, current 65.557121/647: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.557121
last_received_ts = 65.556412
last_seq = 647
current_ts = 65.576195
current_received_ts = 65.575478
current_seq = 648
count = 214
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.557121/647, current 65.576195/648: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.576195
last_received_ts = 65.575478
last_seq = 648
current_ts = 65.595261
current_received_ts = 65.594551
current_seq = 649
count = 215
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.576195/648, current 65.595261/649: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.595261
last_received_ts = 65.594551
last_seq = 649
current_ts = 65.614326
current_received_ts = 65.613617
current_seq = 650
count = 216
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.595261/649, current 65.614326/650: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.614326
last_received_ts = 65.613617
last_seq = 650
current_ts = 65.633400
current_received_ts = 65.632690
current_seq = 651
count = 217
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.614326/650, current 65.633400/651: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.633400
last_received_ts = 65.632690
last_seq = 651
current_ts = 65.652466
current_received_ts = 65.651756
current_seq = 652
count = 218
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.633400/651, current 65.652466/652: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.652466
last_received_ts = 65.651756
last_seq = 652
current_ts = 65.671532
current_received_ts = 65.670822
current_seq = 653
count = 219
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.652466/652, current 65.671532/653: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.671532
last_received_ts = 65.670822
last_seq = 653
current_ts = 65.690605
current_received_ts = 65.689896
current_seq = 654
count = 220
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.671532/653, current 65.690605/654: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.690605
last_received_ts = 65.689896
last_seq = 654
current_ts = 65.709671
current_received_ts = 65.708961
current_seq = 655
count = 221
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.690605/654, current 65.709671/655: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.709671
last_received_ts = 65.708961
last_seq = 655
current_ts = 65.728745
current_received_ts = 65.728035
current_seq = 656
count = 222
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.709671/655, current 65.728745/656: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.728745
last_received_ts = 65.728035
last_seq = 656
current_ts = 65.747810
current_received_ts = 65.747101
current_seq = 657
count = 223
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.728745/656, current 65.747810/657: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.747810
last_received_ts = 65.747101
last_seq = 657
current_ts = 65.766876
current_received_ts = 65.766167
current_seq = 658
count = 224
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.747810/657, current 65.766876/658: elapsed=19068.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.766876
last_received_ts = 65.766167
last_seq = 658
current_ts = 65.785950
current_received_ts = 65.785233
current_seq = 659
count = 225
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.766876/658, current 65.785950/659: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.785950
last_received_ts = 65.785233
last_seq = 659
current_ts = 65.805016
current_received_ts = 65.804306
current_seq = 660
count = 226
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.785950/659, current 65.805016/660: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.805016
last_received_ts = 65.804306
last_seq = 660
current_ts = 65.824074
current_received_ts = 65.823380
current_seq = 661
count = 227
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.805016/660, current 65.824074/661: elapsed=19054.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.824074
last_received_ts = 65.823380
last_seq = 661
current_ts = 65.843140
current_received_ts = 65.842453
current_seq = 662
count = 228
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.824074/661, current 65.843140/662: elapsed=19069.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.843140
last_received_ts = 65.842453
last_seq = 662
current_ts = 65.862213
current_received_ts = 65.861504
current_seq = 663
count = 229
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.843140/662, current 65.862213/663: elapsed=19076.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.862213
last_received_ts = 65.861504
last_seq = 663
current_ts = 65.881271
current_received_ts = 65.880554
current_seq = 664
count = 230
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.862213/663, current 65.881271/664: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.881271
last_received_ts = 65.880554
last_seq = 664
current_ts = 65.900330
current_received_ts = 65.899612
current_seq = 665
count = 231
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.881271/664, current 65.900330/665: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.900330
last_received_ts = 65.899612
last_seq = 665
current_ts = 65.919388
current_received_ts = 65.918671
current_seq = 666
count = 232
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.900330/665, current 65.919388/666: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.919388
last_received_ts = 65.918671
last_seq = 666
current_ts = 65.938446
current_received_ts = 65.937737
current_seq = 667
count = 233
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.919388/666, current 65.938446/667: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.938446
last_received_ts = 65.937737
last_seq = 667
current_ts = 65.957504
current_received_ts = 65.956795
current_seq = 668
count = 234
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.938446/667, current 65.957504/668: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.957504
last_received_ts = 65.956795
last_seq = 668
current_ts = 65.976555
current_received_ts = 65.975845
current_seq = 669
count = 235
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.957504/668, current 65.976555/669: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.976555
last_received_ts = 65.975845
last_seq = 669
current_ts = 65.995613
current_received_ts = 65.994904
current_seq = 670
count = 236
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.976555/669, current 65.995613/670: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 65.995613
last_received_ts = 65.994904
last_seq = 670
current_ts = 66.014671
current_received_ts = 66.013954
current_seq = 671
count = 237
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 65.995613/670, current 66.014671/671: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.014671
last_received_ts = 66.013954
last_seq = 671
current_ts = 66.033730
current_received_ts = 66.033035
current_seq = 672
count = 238
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.014671/671, current 66.033730/672: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.033730
last_received_ts = 66.033035
last_seq = 672
current_ts = 66.052788
current_received_ts = 66.052071
current_seq = 673
count = 239
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.033730/672, current 66.052788/673: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.052788
last_received_ts = 66.052071
last_seq = 673
current_ts = 66.071846
current_received_ts = 66.071129
current_seq = 674
count = 240
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.052788/673, current 66.071846/674: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.071846
last_received_ts = 66.071129
last_seq = 674
current_ts = 66.090897
current_received_ts = 66.090179
current_seq = 675
count = 241
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.071846/674, current 66.090897/675: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.090897
last_received_ts = 66.090179
last_seq = 675
current_ts = 66.109955
current_received_ts = 66.109238
current_seq = 676
count = 242
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.090897/675, current 66.109955/676: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.109955
last_received_ts = 66.109238
last_seq = 676
current_ts = 66.129013
current_received_ts = 66.128296
current_seq = 677
count = 243
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.109955/676, current 66.129013/677: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.129013
last_received_ts = 66.128296
last_seq = 677
current_ts = 66.148056
current_received_ts = 66.147362
current_seq = 678
count = 244
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.129013/677, current 66.148056/678: elapsed=19042.0us expected=19136.1us +- 95.7us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.148056
last_received_ts = 66.147362
last_seq = 678
current_ts = 66.167114
current_received_ts = 66.166420
current_seq = 679
count = 245
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.148056/678, current 66.167114/679: elapsed=19058.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.167114
last_received_ts = 66.166420
last_seq = 679
current_ts = 66.186172
current_received_ts = 66.185478
current_seq = 680
count = 246
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.167114/679, current 66.186172/680: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.186172
last_received_ts = 66.185478
last_seq = 680
current_ts = 66.205231
current_received_ts = 66.204536
current_seq = 681
count = 247
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.186172/680, current 66.205231/681: elapsed=19059.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.205231
last_received_ts = 66.204536
last_seq = 681
current_ts = 66.224289
current_received_ts = 66.223595
current_seq = 682
count = 248
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.205231/681, current 66.224289/682: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.224289
last_received_ts = 66.223595
last_seq = 682
current_ts = 66.243340
current_received_ts = 66.242645
current_seq = 683
count = 249
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.224289/682, current 66.243340/683: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.243340
last_received_ts = 66.242645
last_seq = 683
current_ts = 66.262398
current_received_ts = 66.261703
current_seq = 684
count = 250
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.243340/683, current 66.262398/684: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.262398
last_received_ts = 66.261703
last_seq = 684
current_ts = 66.281456
current_received_ts = 66.280762
current_seq = 685
count = 251
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.262398/684, current 66.281456/685: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.281456
last_received_ts = 66.280762
last_seq = 685
current_ts = 66.300514
current_received_ts = 66.299820
current_seq = 686
count = 252
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.281456/685, current 66.300514/686: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.300514
last_received_ts = 66.299820
last_seq = 686
current_ts = 66.319572
current_received_ts = 66.318878
current_seq = 687
count = 253
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.300514/686, current 66.319572/687: elapsed=19058.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.319572
last_received_ts = 66.318878
last_seq = 687
current_ts = 66.338623
current_received_ts = 66.337929
current_seq = 688
count = 254
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.319572/687, current 66.338623/688: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.338623
last_received_ts = 66.337929
last_seq = 688
current_ts = 66.357681
current_received_ts = 66.356979
current_seq = 689
count = 255
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.338623/688, current 66.357681/689: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.357681
last_received_ts = 66.356979
last_seq = 689
current_ts = 66.376740
current_received_ts = 66.376068
current_seq = 690
count = 256
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.357681/689, current 66.376740/690: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.376740
last_received_ts = 66.376068
last_seq = 690
current_ts = 66.395798
current_received_ts = 66.395096
current_seq = 691
count = 257
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.376740/690, current 66.395798/691: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.395798
last_received_ts = 66.395096
last_seq = 691
current_ts = 66.414856
current_received_ts = 66.414154
current_seq = 692
count = 258
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.395798/691, current 66.414856/692: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.414856
last_received_ts = 66.414154
last_seq = 692
current_ts = 66.433914
current_received_ts = 66.433212
current_seq = 693
count = 259
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.414856/692, current 66.433914/693: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.433914
last_received_ts = 66.433212
last_seq = 693
current_ts = 66.452988
current_received_ts = 66.452271
current_seq = 694
count = 260
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.433914/693, current 66.452988/694: elapsed=19073.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.452988
last_received_ts = 66.452271
last_seq = 694
current_ts = 66.472023
current_received_ts = 66.471329
current_seq = 695
count = 261
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.452988/694, current 66.472023/695: elapsed=19041.0us expected=19136.1us +- 95.7us, error 0.5%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.472023
last_received_ts = 66.471329
last_seq = 695
current_ts = 66.491081
current_received_ts = 66.490387
current_seq = 696
count = 262
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.472023/695, current 66.491081/696: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.491081
last_received_ts = 66.490387
last_seq = 696
current_ts = 66.510139
current_received_ts = 66.509445
current_seq = 697
count = 263
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.491081/696, current 66.510139/697: elapsed=19059.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.510139
last_received_ts = 66.509445
last_seq = 697
current_ts = 66.529198
current_received_ts = 66.528503
current_seq = 698
count = 264
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.510139/697, current 66.529198/698: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.529198
last_received_ts = 66.528503
last_seq = 698
current_ts = 66.548256
current_received_ts = 66.547562
current_seq = 699
count = 265
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.529198/698, current 66.548256/699: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.548256
last_received_ts = 66.547562
last_seq = 699
current_ts = 66.567314
current_received_ts = 66.566620
current_seq = 700
count = 266
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.548256/699, current 66.567314/700: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.567314
last_received_ts = 66.566620
last_seq = 700
current_ts = 66.586372
current_received_ts = 66.585678
current_seq = 701
count = 267
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.567314/700, current 66.586372/701: elapsed=19058.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.586372
last_received_ts = 66.585678
last_seq = 701
current_ts = 66.605423
current_received_ts = 66.604736
current_seq = 702
count = 268
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.586372/701, current 66.605423/702: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.605423
last_received_ts = 66.604736
last_seq = 702
current_ts = 66.624481
current_received_ts = 66.623787
current_seq = 703
count = 269
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.605423/702, current 66.624481/703: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.624481
last_received_ts = 66.623787
last_seq = 703
current_ts = 66.643539
current_received_ts = 66.642838
current_seq = 704
count = 270
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.624481/703, current 66.643539/704: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.643539
last_received_ts = 66.642838
last_seq = 704
current_ts = 66.662598
current_received_ts = 66.661896
current_seq = 705
count = 271
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.643539/704, current 66.662598/705: elapsed=19057.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.662598
last_received_ts = 66.661896
last_seq = 705
current_ts = 66.681656
current_received_ts = 66.680954
current_seq = 706
count = 272
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.662598/705, current 66.681656/706: elapsed=19058.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.681656
last_received_ts = 66.680954
last_seq = 706
current_ts = 66.700706
current_received_ts = 66.700035
current_seq = 707
count = 273
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.681656/706, current 66.700706/707: elapsed=19056.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.700706
last_received_ts = 66.700035
last_seq = 707
current_ts = 66.719772
current_received_ts = 66.719078
current_seq = 708
count = 274
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.700706/707, current 66.719772/708: elapsed=19063.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.719772
last_received_ts = 66.719078
last_seq = 708
current_ts = 66.738823
current_received_ts = 66.738121
current_seq = 709
count = 275
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.719772/708, current 66.738823/709: elapsed=19051.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.738823
last_received_ts = 66.738121
last_seq = 709
current_ts = 66.757881
current_received_ts = 66.757179
current_seq = 710
count = 276
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.738823/709, current 66.757881/710: elapsed=19058.0us expected=19136.1us +- 95.7us, error 0.4%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.757881
last_received_ts = 66.757179
last_seq = 710
current_ts = 66.776955
current_received_ts = 66.776237
current_seq = 711
count = 277
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.757881/710, current 66.776955/711: elapsed=19073.0us expected=19136.1us +- 95.7us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 66.776955
last_received_ts = 66.776237
last_seq = 711
current_ts = 66.795998
current_received_ts = 66.795296
current_seq = 712
count = 278
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 66.776955/711, current 66.795998/712: elapsed=19040.0us expected=19136.1us +- 95.7us, error 0.5%
(kms_flip:2058) DEBUG: inconsistent flip ts/seq: last 66.776955/711, current 66.795998/712: elapsed=19040.0us expected=19136.1us
(kms_flip:2058) DEBUG: expected 0, counted 278, encoder type 2
(kms_flip:2058) DEBUG: dropped frames, expected 0, counted 278, encoder type 2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2058) igt_core-INFO: Stack trace:
(kms_flip:2058) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2058) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2058) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2058) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2058) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2058) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2058) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2058) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (9.031s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.220604
last_received_ts = 83.219910
last_seq = 689
current_ts = 83.239586
current_received_ts = 83.238892
current_seq = 690
count = 669
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.220604/689, current 83.239586/690: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.239586
last_received_ts = 83.238892
last_seq = 690
current_ts = 83.258568
current_received_ts = 83.257874
current_seq = 691
count = 670
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.239586/690, current 83.258568/691: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.258568
last_received_ts = 83.257874
last_seq = 691
current_ts = 83.277550
current_received_ts = 83.276855
current_seq = 692
count = 671
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.258568/691, current 83.277550/692: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.277550
last_received_ts = 83.276855
last_seq = 692
current_ts = 83.296532
current_received_ts = 83.295837
current_seq = 693
count = 672
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.277550/692, current 83.296532/693: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.296532
last_received_ts = 83.295837
last_seq = 693
current_ts = 83.315514
current_received_ts = 83.314819
current_seq = 694
count = 673
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.296532/693, current 83.315514/694: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.315514
last_received_ts = 83.314819
last_seq = 694
current_ts = 83.334496
current_received_ts = 83.333801
current_seq = 695
count = 674
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.315514/694, current 83.334496/695: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.334496
last_received_ts = 83.333801
last_seq = 695
current_ts = 83.353477
current_received_ts = 83.352783
current_seq = 696
count = 675
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.334496/695, current 83.353477/696: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.353477
last_received_ts = 83.352783
last_seq = 696
current_ts = 83.372459
current_received_ts = 83.371765
current_seq = 697
count = 676
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.353477/696, current 83.372459/697: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.372459
last_received_ts = 83.371765
last_seq = 697
current_ts = 83.391441
current_received_ts = 83.390747
current_seq = 698
count = 677
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.372459/697, current 83.391441/698: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.391441
last_received_ts = 83.390747
last_seq = 698
current_ts = 83.410423
current_received_ts = 83.409737
current_seq = 699
count = 678
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.391441/698, current 83.410423/699: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.410423
last_received_ts = 83.409737
last_seq = 699
current_ts = 83.429405
current_received_ts = 83.428719
current_seq = 700
count = 679
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.410423/699, current 83.429405/700: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.429405
last_received_ts = 83.428719
last_seq = 700
current_ts = 83.448387
current_received_ts = 83.447693
current_seq = 701
count = 680
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.429405/700, current 83.448387/701: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.448387
last_received_ts = 83.447693
last_seq = 701
current_ts = 83.467377
current_received_ts = 83.466675
current_seq = 702
count = 681
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.448387/701, current 83.467377/702: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.467377
last_received_ts = 83.466675
last_seq = 702
current_ts = 83.486359
current_received_ts = 83.485664
current_seq = 703
count = 682
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.467377/702, current 83.486359/703: elapsed=18984.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.486359
last_received_ts = 83.485664
last_seq = 703
current_ts = 83.505341
current_received_ts = 83.504639
current_seq = 704
count = 683
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.486359/703, current 83.505341/704: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.505341
last_received_ts = 83.504639
last_seq = 704
current_ts = 83.524323
current_received_ts = 83.523621
current_seq = 705
count = 684
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.505341/704, current 83.524323/705: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.524323
last_received_ts = 83.523621
last_seq = 705
current_ts = 83.543304
current_received_ts = 83.542603
current_seq = 706
count = 685
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.524323/705, current 83.543304/706: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.543304
last_received_ts = 83.542603
last_seq = 706
current_ts = 83.562286
current_received_ts = 83.561592
current_seq = 707
count = 686
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.543304/706, current 83.562286/707: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.562286
last_received_ts = 83.561592
last_seq = 707
current_ts = 83.581268
current_received_ts = 83.580574
current_seq = 708
count = 687
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.562286/707, current 83.581268/708: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.581268
last_received_ts = 83.580574
last_seq = 708
current_ts = 83.600250
current_received_ts = 83.599556
current_seq = 709
count = 688
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.581268/708, current 83.600250/709: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.600250
last_received_ts = 83.599556
last_seq = 709
current_ts = 83.619232
current_received_ts = 83.618538
current_seq = 710
count = 689
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.600250/709, current 83.619232/710: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.619232
last_received_ts = 83.618538
last_seq = 710
current_ts = 83.638214
current_received_ts = 83.637527
current_seq = 711
count = 690
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.619232/710, current 83.638214/711: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.638214
last_received_ts = 83.637527
last_seq = 711
current_ts = 83.657196
current_received_ts = 83.656502
current_seq = 712
count = 691
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.638214/711, current 83.657196/712: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.657196
last_received_ts = 83.656502
last_seq = 712
current_ts = 83.676178
current_received_ts = 83.675484
current_seq = 713
count = 692
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.657196/712, current 83.676178/713: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.676178
last_received_ts = 83.675484
last_seq = 713
current_ts = 83.695160
current_received_ts = 83.694466
current_seq = 714
count = 693
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.676178/713, current 83.695160/714: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.695160
last_received_ts = 83.694466
last_seq = 714
current_ts = 83.714142
current_received_ts = 83.713448
current_seq = 715
count = 694
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.695160/714, current 83.714142/715: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.714142
last_received_ts = 83.713448
last_seq = 715
current_ts = 83.733124
current_received_ts = 83.732430
current_seq = 716
count = 695
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.714142/715, current 83.733124/716: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.733124
last_received_ts = 83.732430
last_seq = 716
current_ts = 83.752106
current_received_ts = 83.751411
current_seq = 717
count = 696
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.733124/716, current 83.752106/717: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.752106
last_received_ts = 83.751411
last_seq = 717
current_ts = 83.771095
current_received_ts = 83.770401
current_seq = 718
count = 697
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.752106/717, current 83.771095/718: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.771095
last_received_ts = 83.770401
last_seq = 718
current_ts = 83.790070
current_received_ts = 83.789375
current_seq = 719
count = 698
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.771095/718, current 83.790070/719: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.790070
last_received_ts = 83.789375
last_seq = 719
current_ts = 83.809052
current_received_ts = 83.808357
current_seq = 720
count = 699
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.790070/719, current 83.809052/720: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.809052
last_received_ts = 83.808357
last_seq = 720
current_ts = 83.828041
current_received_ts = 83.827339
current_seq = 721
count = 700
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.809052/720, current 83.828041/721: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.828041
last_received_ts = 83.827339
last_seq = 721
current_ts = 83.847023
current_received_ts = 83.846321
current_seq = 722
count = 701
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.828041/721, current 83.847023/722: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.847023
last_received_ts = 83.846321
last_seq = 722
current_ts = 83.865997
current_received_ts = 83.865303
current_seq = 723
count = 702
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.847023/722, current 83.865997/723: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.865997
last_received_ts = 83.865303
last_seq = 723
current_ts = 83.884979
current_received_ts = 83.884285
current_seq = 724
count = 703
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.865997/723, current 83.884979/724: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.884979
last_received_ts = 83.884285
last_seq = 724
current_ts = 83.903961
current_received_ts = 83.903267
current_seq = 725
count = 704
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.884979/724, current 83.903961/725: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.903961
last_received_ts = 83.903267
last_seq = 725
current_ts = 83.922943
current_received_ts = 83.922249
current_seq = 726
count = 705
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.903961/725, current 83.922943/726: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.922943
last_received_ts = 83.922249
last_seq = 726
current_ts = 83.941925
current_received_ts = 83.941231
current_seq = 727
count = 706
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.922943/726, current 83.941925/727: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.941925
last_received_ts = 83.941231
last_seq = 727
current_ts = 83.960907
current_received_ts = 83.960213
current_seq = 728
count = 707
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.941925/727, current 83.960907/728: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.960907
last_received_ts = 83.960213
last_seq = 728
current_ts = 83.979889
current_received_ts = 83.979195
current_seq = 729
count = 708
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.960907/728, current 83.979889/729: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.979889
last_received_ts = 83.979195
last_seq = 729
current_ts = 83.998871
current_received_ts = 83.998177
current_seq = 730
count = 709
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.979889/729, current 83.998871/730: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 83.998871
last_received_ts = 83.998177
last_seq = 730
current_ts = 84.017853
current_received_ts = 84.017159
current_seq = 731
count = 710
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 83.998871/730, current 84.017853/731: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.017853
last_received_ts = 84.017159
last_seq = 731
current_ts = 84.036835
current_received_ts = 84.036133
current_seq = 732
count = 711
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.017853/731, current 84.036835/732: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.036835
last_received_ts = 84.036133
last_seq = 732
current_ts = 84.055817
current_received_ts = 84.055115
current_seq = 733
count = 712
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.036835/732, current 84.055817/733: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.055817
last_received_ts = 84.055115
last_seq = 733
current_ts = 84.074799
current_received_ts = 84.074097
current_seq = 734
count = 713
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.055817/733, current 84.074799/734: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.074799
last_received_ts = 84.074097
last_seq = 734
current_ts = 84.093781
current_received_ts = 84.093079
current_seq = 735
count = 714
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.074799/734, current 84.093781/735: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.093781
last_received_ts = 84.093079
last_seq = 735
current_ts = 84.112770
current_received_ts = 84.112076
current_seq = 736
count = 715
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.093781/735, current 84.112770/736: elapsed=18991.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.112770
last_received_ts = 84.112076
last_seq = 736
current_ts = 84.131737
current_received_ts = 84.131065
current_seq = 737
count = 716
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.112770/736, current 84.131737/737: elapsed=18972.0us expected=19021.6us +- 95.1us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.131737
last_received_ts = 84.131065
last_seq = 737
current_ts = 84.150719
current_received_ts = 84.150047
current_seq = 738
count = 717
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.131737/737, current 84.150719/738: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.150719
last_received_ts = 84.150047
last_seq = 738
current_ts = 84.169701
current_received_ts = 84.169037
current_seq = 739
count = 718
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.150719/738, current 84.169701/739: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.169701
last_received_ts = 84.169037
last_seq = 739
current_ts = 84.188683
current_received_ts = 84.187988
current_seq = 740
count = 719
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.169701/739, current 84.188683/740: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.188683
last_received_ts = 84.187988
last_seq = 740
current_ts = 84.207664
current_received_ts = 84.206970
current_seq = 741
count = 720
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.188683/740, current 84.207664/741: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.207664
last_received_ts = 84.206970
last_seq = 741
current_ts = 84.226646
current_received_ts = 84.225952
current_seq = 742
count = 721
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.207664/741, current 84.226646/742: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.226646
last_received_ts = 84.225952
last_seq = 742
current_ts = 84.245628
current_received_ts = 84.244942
current_seq = 743
count = 722
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.226646/742, current 84.245628/743: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.245628
last_received_ts = 84.244942
last_seq = 743
current_ts = 84.264610
current_received_ts = 84.263916
current_seq = 744
count = 723
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.245628/743, current 84.264610/744: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.264610
last_received_ts = 84.263916
last_seq = 744
current_ts = 84.283592
current_received_ts = 84.282898
current_seq = 745
count = 724
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.264610/744, current 84.283592/745: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.283592
last_received_ts = 84.282898
last_seq = 745
current_ts = 84.302574
current_received_ts = 84.301872
current_seq = 746
count = 725
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.283592/745, current 84.302574/746: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.302574
last_received_ts = 84.301872
last_seq = 746
current_ts = 84.321556
current_received_ts = 84.320854
current_seq = 747
count = 726
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.302574/746, current 84.321556/747: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.321556
last_received_ts = 84.320854
last_seq = 747
current_ts = 84.340530
current_received_ts = 84.339836
current_seq = 748
count = 727
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.321556/747, current 84.340530/748: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.340530
last_received_ts = 84.339836
last_seq = 748
current_ts = 84.359512
current_received_ts = 84.358818
current_seq = 749
count = 728
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.340530/748, current 84.359512/749: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.359512
last_received_ts = 84.358818
last_seq = 749
current_ts = 84.378494
current_received_ts = 84.377800
current_seq = 750
count = 729
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.359512/749, current 84.378494/750: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.378494
last_received_ts = 84.377800
last_seq = 750
current_ts = 84.397476
current_received_ts = 84.396790
current_seq = 751
count = 730
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.378494/750, current 84.397476/751: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.397476
last_received_ts = 84.396790
last_seq = 751
current_ts = 84.416458
current_received_ts = 84.415764
current_seq = 752
count = 731
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.397476/751, current 84.416458/752: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.416458
last_received_ts = 84.415764
last_seq = 752
current_ts = 84.435440
current_received_ts = 84.434753
current_seq = 753
count = 732
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.416458/752, current 84.435440/753: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.435440
last_received_ts = 84.434753
last_seq = 753
current_ts = 84.454422
current_received_ts = 84.453728
current_seq = 754
count = 733
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.435440/753, current 84.454422/754: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.454422
last_received_ts = 84.453728
last_seq = 754
current_ts = 84.473404
current_received_ts = 84.472710
current_seq = 755
count = 734
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.454422/754, current 84.473404/755: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.473404
last_received_ts = 84.472710
last_seq = 755
current_ts = 84.492386
current_received_ts = 84.491692
current_seq = 756
count = 735
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.473404/755, current 84.492386/756: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.492386
last_received_ts = 84.491692
last_seq = 756
current_ts = 84.511368
current_received_ts = 84.510666
current_seq = 757
count = 736
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.492386/756, current 84.511368/757: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.511368
last_received_ts = 84.510666
last_seq = 757
current_ts = 84.530350
current_received_ts = 84.529648
current_seq = 758
count = 737
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.511368/757, current 84.530350/758: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.530350
last_received_ts = 84.529648
last_seq = 758
current_ts = 84.549332
current_received_ts = 84.548630
current_seq = 759
count = 738
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.530350/758, current 84.549332/759: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.549332
last_received_ts = 84.548630
last_seq = 759
current_ts = 84.568314
current_received_ts = 84.567619
current_seq = 760
count = 739
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.549332/759, current 84.568314/760: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.568314
last_received_ts = 84.567619
last_seq = 760
current_ts = 84.587288
current_received_ts = 84.586594
current_seq = 761
count = 740
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.568314/760, current 84.587288/761: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.587288
last_received_ts = 84.586594
last_seq = 761
current_ts = 84.606270
current_received_ts = 84.605576
current_seq = 762
count = 741
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.587288/761, current 84.606270/762: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.606270
last_received_ts = 84.605576
last_seq = 762
current_ts = 84.625252
current_received_ts = 84.624557
current_seq = 763
count = 742
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.606270/762, current 84.625252/763: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.625252
last_received_ts = 84.624557
last_seq = 763
current_ts = 84.644234
current_received_ts = 84.643539
current_seq = 764
count = 743
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.625252/763, current 84.644234/764: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.644234
last_received_ts = 84.643539
last_seq = 764
current_ts = 84.663216
current_received_ts = 84.662521
current_seq = 765
count = 744
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.644234/764, current 84.663216/765: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.663216
last_received_ts = 84.662521
last_seq = 765
current_ts = 84.682198
current_received_ts = 84.681503
current_seq = 766
count = 745
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.663216/765, current 84.682198/766: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.682198
last_received_ts = 84.681503
last_seq = 766
current_ts = 84.701180
current_received_ts = 84.700485
current_seq = 767
count = 746
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.682198/766, current 84.701180/767: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.701180
last_received_ts = 84.700485
last_seq = 767
current_ts = 84.720161
current_received_ts = 84.719467
current_seq = 768
count = 747
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.701180/767, current 84.720161/768: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.720161
last_received_ts = 84.719467
last_seq = 768
current_ts = 84.739143
current_received_ts = 84.738441
current_seq = 769
count = 748
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.720161/768, current 84.739143/769: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.739143
last_received_ts = 84.738441
last_seq = 769
current_ts = 84.758125
current_received_ts = 84.757423
current_seq = 770
count = 749
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.739143/769, current 84.758125/770: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.758125
last_received_ts = 84.757423
last_seq = 770
current_ts = 84.777100
current_received_ts = 84.776405
current_seq = 771
count = 750
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.758125/770, current 84.777100/771: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.777100
last_received_ts = 84.776405
last_seq = 771
current_ts = 84.796082
current_received_ts = 84.795387
current_seq = 772
count = 751
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.777100/771, current 84.796082/772: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.796082
last_received_ts = 84.795387
last_seq = 772
current_ts = 84.815063
current_received_ts = 84.814369
current_seq = 773
count = 752
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.796082/772, current 84.815063/773: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.815063
last_received_ts = 84.814369
last_seq = 773
current_ts = 84.834045
current_received_ts = 84.833351
current_seq = 774
count = 753
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.815063/773, current 84.834045/774: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.834045
last_received_ts = 84.833351
last_seq = 774
current_ts = 84.853027
current_received_ts = 84.852333
current_seq = 775
count = 754
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.834045/774, current 84.853027/775: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.853027
last_received_ts = 84.852333
last_seq = 775
current_ts = 84.872009
current_received_ts = 84.871315
current_seq = 776
count = 755
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.853027/775, current 84.872009/776: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.872009
last_received_ts = 84.871315
last_seq = 776
current_ts = 84.890991
current_received_ts = 84.890297
current_seq = 777
count = 756
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.872009/776, current 84.890991/777: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.890991
last_received_ts = 84.890297
last_seq = 777
current_ts = 84.909973
current_received_ts = 84.909271
current_seq = 778
count = 757
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.890991/777, current 84.909973/778: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.909973
last_received_ts = 84.909271
last_seq = 778
current_ts = 84.928947
current_received_ts = 84.928253
current_seq = 779
count = 758
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.909973/778, current 84.928947/779: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.928947
last_received_ts = 84.928253
last_seq = 779
current_ts = 84.947929
current_received_ts = 84.947235
current_seq = 780
count = 759
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.928947/779, current 84.947929/780: elapsed=18979.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.947929
last_received_ts = 84.947235
last_seq = 780
current_ts = 84.966911
current_received_ts = 84.966217
current_seq = 781
count = 760
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.947929/780, current 84.966911/781: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.966911
last_received_ts = 84.966217
last_seq = 781
current_ts = 84.985893
current_received_ts = 84.985199
current_seq = 782
count = 761
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.966911/781, current 84.985893/782: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 84.985893
last_received_ts = 84.985199
last_seq = 782
current_ts = 85.004875
current_received_ts = 85.004173
current_seq = 783
count = 762
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 84.985893/782, current 85.004875/783: elapsed=18979.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.004875
last_received_ts = 85.004173
last_seq = 783
current_ts = 85.023849
current_received_ts = 85.026222
current_seq = 784
count = 763
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.004875/783, current 85.023849/784: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.023849
last_received_ts = 85.026222
last_seq = 784
current_ts = 85.042831
current_received_ts = 85.042175
current_seq = 785
count = 764
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.023849/784, current 85.042831/785: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.042831
last_received_ts = 85.042175
last_seq = 785
current_ts = 85.061821
current_received_ts = 85.061089
current_seq = 786
count = 765
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.042831/785, current 85.061821/786: elapsed=18986.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.061821
last_received_ts = 85.061089
last_seq = 786
current_ts = 85.080803
current_received_ts = 85.080063
current_seq = 787
count = 766
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.061821/786, current 85.080803/787: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.080803
last_received_ts = 85.080063
last_seq = 787
current_ts = 85.099785
current_received_ts = 85.099060
current_seq = 788
count = 767
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.080803/787, current 85.099785/788: elapsed=18983.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.099785
last_received_ts = 85.099060
last_seq = 788
current_ts = 85.118759
current_received_ts = 85.118103
current_seq = 789
count = 768
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.099785/788, current 85.118759/789: elapsed=18975.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.118759
last_received_ts = 85.118103
last_seq = 789
current_ts = 85.137733
current_received_ts = 85.137070
current_seq = 790
count = 769
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.118759/789, current 85.137733/790: elapsed=18974.0us expected=19021.6us +- 95.1us, error 0.3%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.137733
last_received_ts = 85.137070
last_seq = 790
current_ts = 85.156715
current_received_ts = 85.156059
current_seq = 791
count = 770
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.137733/790, current 85.156715/791: elapsed=18982.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.156715
last_received_ts = 85.156059
last_seq = 791
current_ts = 85.175697
current_received_ts = 85.175056
current_seq = 792
count = 771
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.156715/791, current 85.175697/792: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.175697
last_received_ts = 85.175056
last_seq = 792
current_ts = 85.194679
current_received_ts = 85.194046
current_seq = 793
count = 772
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.175697/792, current 85.194679/793: elapsed=18985.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.194679
last_received_ts = 85.194046
last_seq = 793
current_ts = 85.213654
current_received_ts = 85.212982
current_seq = 794
count = 773
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.194679/793, current 85.213654/794: elapsed=18975.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.213654
last_received_ts = 85.212982
last_seq = 794
current_ts = 85.232635
current_received_ts = 85.231964
current_seq = 795
count = 774
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.213654/794, current 85.232635/795: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.232635
last_received_ts = 85.231964
last_seq = 795
current_ts = 85.251617
current_received_ts = 85.250923
current_seq = 796
count = 775
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.232635/795, current 85.251617/796: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.251617
last_received_ts = 85.250923
last_seq = 796
current_ts = 85.270599
current_received_ts = 85.269897
current_seq = 797
count = 776
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.251617/796, current 85.270599/797: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.270599
last_received_ts = 85.269897
last_seq = 797
current_ts = 85.289574
current_received_ts = 85.288879
current_seq = 798
count = 777
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.270599/797, current 85.289574/798: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.289574
last_received_ts = 85.288879
last_seq = 798
current_ts = 85.308556
current_received_ts = 85.307861
current_seq = 799
count = 778
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.289574/798, current 85.308556/799: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.308556
last_received_ts = 85.307861
last_seq = 799
current_ts = 85.327538
current_received_ts = 85.326843
current_seq = 800
count = 779
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.308556/799, current 85.327538/800: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.327538
last_received_ts = 85.326843
last_seq = 800
current_ts = 85.346519
current_received_ts = 85.345818
current_seq = 801
count = 780
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.327538/800, current 85.346519/801: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.346519
last_received_ts = 85.345818
last_seq = 801
current_ts = 85.365494
current_received_ts = 85.364799
current_seq = 802
count = 781
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.346519/801, current 85.365494/802: elapsed=18979.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.365494
last_received_ts = 85.364799
last_seq = 802
current_ts = 85.384476
current_received_ts = 85.383781
current_seq = 803
count = 782
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.365494/802, current 85.384476/803: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.384476
last_received_ts = 85.383781
last_seq = 803
current_ts = 85.403458
current_received_ts = 85.402763
current_seq = 804
count = 783
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.384476/803, current 85.403458/804: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.403458
last_received_ts = 85.402763
last_seq = 804
current_ts = 85.422440
current_received_ts = 85.421745
current_seq = 805
count = 784
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.403458/804, current 85.422440/805: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.422440
last_received_ts = 85.421745
last_seq = 805
current_ts = 85.441422
current_received_ts = 85.440720
current_seq = 806
count = 785
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.422440/805, current 85.441422/806: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.441422
last_received_ts = 85.440720
last_seq = 806
current_ts = 85.460396
current_received_ts = 85.459702
current_seq = 807
count = 786
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.441422/806, current 85.460396/807: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.460396
last_received_ts = 85.459702
last_seq = 807
current_ts = 85.479378
current_received_ts = 85.478683
current_seq = 808
count = 787
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.460396/807, current 85.479378/808: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.479378
last_received_ts = 85.478683
last_seq = 808
current_ts = 85.498360
current_received_ts = 85.497665
current_seq = 809
count = 788
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.479378/808, current 85.498360/809: elapsed=18980.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: name = flip
last_ts = 85.498360
last_received_ts = 85.497665
last_seq = 809
current_ts = 85.517342
current_received_ts = 85.516647
current_seq = 810
count = 789
seq_step = 1
(kms_flip:2058) DEBUG: flip ts/seq: last 85.498360/809, current 85.517342/810: elapsed=18981.0us expected=19021.6us +- 95.1us, error 0.2%
(kms_flip:2058) DEBUG: expected 788, counted 790, encoder type 2
(kms_flip:2058) DEBUG: dropped frames, expected 788, counted 790, encoder type 2
(kms_flip:2058) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2058) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2058) igt_core-INFO: Stack trace:
(kms_flip:2058) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2058) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2058) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2058) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2058) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2058) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2058) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2058) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (18.658s)
Subtest plain-flip-ts-check: FAIL (27.694s)
(kms_flip:2058) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2058) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2058) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2058) igt_kms-CRITICAL: DPMS property not found on 137