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

shard-tglu-4

IGT-Version: 1.30-gedf352a96 (x86_64) (Linux: 6.13.0-rc2-CI_DRM_15843-g3002940575eb+ x86_64)

Using IGT_SRANDOM=1734147146 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 8339.0us +- 3.559us accuracy 0.13%
Stack trace:
  #0 ../lib/igt_core.c:2051 __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 (3.501s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8466.9us +- 3.828us accuracy 0.14%
vblank interval differs from modeline! expected 8334.6us, measured 8467us +- 3.828us, difference 132.3us (34.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __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 (5.988s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8396.4us +- 2.683us accuracy 0.10%
vblank interval differs from modeline! expected 8334.6us, measured 8396us +- 2.683us, difference 61.9us (23.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __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 C-HDMI-A1: FAIL (10.925s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8351.9us +- 2.802us accuracy 0.10%
vblank interval differs from modeline! expected 8334.6us, measured 8352us +- 2.802us, difference 17.3us (6.2 sigma)
Dynamic subtest D-HDMI-A1: SUCCESS (7.830s)
Subtest plain-flip-ts-check: FAIL (28.251s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2198) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2198) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2198) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2198) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2198) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2198) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2198) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2198) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2198) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2198) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2198) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2198) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2198) igt_kms-INFO:   1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
(kms_flip:2198) DEBUG: No stale events found
(kms_flip:2198) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2198) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2198) INFO: Expected frametime: 8335us; measured 8339.0us +- 3.559us accuracy 0.13%
(kms_flip:2198) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 176.215668
current_received_ts = 176.215393
current_seq = 15487
count = 0
seq_step = 1
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.215668
last_received_ts = 176.215393
last_seq = 15487
current_ts = 176.224014
current_received_ts = 176.223801
current_seq = 15488
count = 1
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.215668/15487, current 176.224014/15488: elapsed=8338.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.224014
last_received_ts = 176.223801
last_seq = 15488
current_ts = 176.232346
current_received_ts = 176.232162
current_seq = 15489
count = 2
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.224014/15488, current 176.232346/15489: elapsed=8339.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.232346
last_received_ts = 176.232162
last_seq = 15489
current_ts = 176.240692
current_received_ts = 176.240402
current_seq = 15490
count = 3
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.232346/15489, current 176.240692/15490: elapsed=8341.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.240692
last_received_ts = 176.240402
last_seq = 15490
current_ts = 176.249023
current_received_ts = 176.248810
current_seq = 15491
count = 4
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.240692/15490, current 176.249023/15491: elapsed=8338.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.249023
last_received_ts = 176.248810
last_seq = 15491
current_ts = 176.257355
current_received_ts = 176.257080
current_seq = 15492
count = 5
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.249023/15491, current 176.257355/15492: elapsed=8335.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.257355
last_received_ts = 176.257080
last_seq = 15492
current_ts = 176.265701
current_received_ts = 176.265427
current_seq = 15493
count = 6
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.257355/15492, current 176.265701/15493: elapsed=8341.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.265701
last_received_ts = 176.265427
last_seq = 15493
current_ts = 176.274048
current_received_ts = 176.273758
current_seq = 15494
count = 7
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.265701/15493, current 176.274048/15494: elapsed=8340.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.274048
last_received_ts = 176.273758
last_seq = 15494
current_ts = 176.282379
current_received_ts = 176.282089
current_seq = 15495
count = 8
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.274048/15494, current 176.282379/15495: elapsed=8340.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.282379
last_received_ts = 176.282089
last_seq = 15495
current_ts = 176.290710
current_received_ts = 176.290451
current_seq = 15496
count = 9
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.282379/15495, current 176.290710/15496: elapsed=8335.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.290710
last_received_ts = 176.290451
last_seq = 15496
current_ts = 176.299057
current_received_ts = 176.298737
current_seq = 15497
count = 10
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.290710/15496, current 176.299057/15497: elapsed=8339.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.299057
last_received_ts = 176.298737
last_seq = 15497
current_ts = 176.307404
current_received_ts = 176.307083
current_seq = 15498
count = 11
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.299057/15497, current 176.307404/15498: elapsed=8341.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.307404
last_received_ts = 176.307083
last_seq = 15498
current_ts = 176.315735
current_received_ts = 176.315536
current_seq = 15499
count = 12
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.307404/15498, current 176.315735/15499: elapsed=8339.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.315735
last_received_ts = 176.315536
last_seq = 15499
current_ts = 176.324081
current_received_ts = 176.323746
current_seq = 15500
count = 13
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.315735/15499, current 176.324081/15500: elapsed=8339.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.324081
last_received_ts = 176.323746
last_seq = 15500
current_ts = 176.332413
current_received_ts = 176.332169
current_seq = 15501
count = 14
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.324081/15500, current 176.332413/15501: elapsed=8337.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.332413
last_received_ts = 176.332169
last_seq = 15501
current_ts = 176.340759
current_received_ts = 176.340393
current_seq = 15502
count = 15
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.332413/15501, current 176.340759/15502: elapsed=8341.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.340759
last_received_ts = 176.340393
last_seq = 15502
current_ts = 176.349091
current_received_ts = 176.348724
current_seq = 15503
count = 16
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.340759/15502, current 176.349091/15503: elapsed=8340.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.349091
last_received_ts = 176.348724
last_seq = 15503
current_ts = 176.357437
current_received_ts = 176.357147
current_seq = 15504
count = 17
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.349091/15503, current 176.357437/15504: elapsed=8339.0us expected=8339.0us +- 41.7us, error 0.0%
(kms_flip:2198) DEBUG: name = flip
last_ts = 176.357437
last_received_ts = 176.357147
last_seq = 15504
current_ts = 176.365967
current_received_ts = 176.365631
current_seq = 15505
count = 18
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 176.357437/15504, current 176.365967/15505: elapsed=8527.0us expected=8339.0us +- 41.7us, error 2.3%
(kms_flip:2198) DEBUG: inconsistent flip ts/seq: last 176.357437/15504, current 176.365967/15505: elapsed=8527.0us expected=8339.0us
(kms_flip:2198) DEBUG: expected 0, counted 18, encoder type 2
(kms_flip:2198) DEBUG: dropped frames, expected 0, counted 18, encoder type 2
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2198) igt_core-INFO: Stack trace:
(kms_flip:2198) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2198) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2198) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2198) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2198) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2198) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2198) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2198) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (3.501s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2198) DEBUG: flip ts/seq: last 181.353439/263, current 181.361877/264: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.361877
last_received_ts = 181.361633
last_seq = 264
current_ts = 181.370300
current_received_ts = 181.370132
current_seq = 265
count = 183
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.361877/264, current 181.370300/265: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.370300
last_received_ts = 181.370132
last_seq = 265
current_ts = 181.378738
current_received_ts = 181.378448
current_seq = 266
count = 184
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.370300/265, current 181.378738/266: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.378738
last_received_ts = 181.378448
last_seq = 266
current_ts = 181.387192
current_received_ts = 181.387054
current_seq = 267
count = 185
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.378738/266, current 181.387192/267: elapsed=8443.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.387192
last_received_ts = 181.387054
last_seq = 267
current_ts = 181.395615
current_received_ts = 181.395355
current_seq = 268
count = 186
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.387192/267, current 181.395615/268: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.395615
last_received_ts = 181.395355
last_seq = 268
current_ts = 181.404053
current_received_ts = 181.403732
current_seq = 269
count = 187
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.395615/268, current 181.404053/269: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.404053
last_received_ts = 181.403732
last_seq = 269
current_ts = 181.412491
current_received_ts = 181.412231
current_seq = 270
count = 188
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.404053/269, current 181.412491/270: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.412491
last_received_ts = 181.412231
last_seq = 270
current_ts = 181.420929
current_received_ts = 181.420593
current_seq = 271
count = 189
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.412491/270, current 181.420929/271: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.420929
last_received_ts = 181.420593
last_seq = 271
current_ts = 181.429367
current_received_ts = 181.429062
current_seq = 272
count = 190
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.420929/271, current 181.429367/272: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.429367
last_received_ts = 181.429062
last_seq = 272
current_ts = 181.437805
current_received_ts = 181.437469
current_seq = 273
count = 191
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.429367/272, current 181.437805/273: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.437805
last_received_ts = 181.437469
last_seq = 273
current_ts = 181.446243
current_received_ts = 181.445923
current_seq = 274
count = 192
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.437805/273, current 181.446243/274: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.446243
last_received_ts = 181.445923
last_seq = 274
current_ts = 181.454681
current_received_ts = 181.454361
current_seq = 275
count = 193
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.446243/274, current 181.454681/275: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.454681
last_received_ts = 181.454361
last_seq = 275
current_ts = 181.463120
current_received_ts = 181.462845
current_seq = 276
count = 194
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.454681/275, current 181.463120/276: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.463120
last_received_ts = 181.462845
last_seq = 276
current_ts = 181.471542
current_received_ts = 181.471298
current_seq = 277
count = 195
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.463120/276, current 181.471542/277: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.471542
last_received_ts = 181.471298
last_seq = 277
current_ts = 181.479980
current_received_ts = 181.479767
current_seq = 278
count = 196
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.471542/277, current 181.479980/278: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.479980
last_received_ts = 181.479767
last_seq = 278
current_ts = 181.488419
current_received_ts = 181.488174
current_seq = 279
count = 197
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.479980/278, current 181.488419/279: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.488419
last_received_ts = 181.488174
last_seq = 279
current_ts = 181.496857
current_received_ts = 181.496628
current_seq = 280
count = 198
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.488419/279, current 181.496857/280: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.496857
last_received_ts = 181.496628
last_seq = 280
current_ts = 181.505295
current_received_ts = 181.504974
current_seq = 281
count = 199
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.496857/280, current 181.505295/281: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.505295
last_received_ts = 181.504974
last_seq = 281
current_ts = 181.513733
current_received_ts = 181.513412
current_seq = 282
count = 200
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.505295/281, current 181.513733/282: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.513733
last_received_ts = 181.513412
last_seq = 282
current_ts = 181.522171
current_received_ts = 181.521957
current_seq = 283
count = 201
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.513733/282, current 181.522171/283: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.522171
last_received_ts = 181.521957
last_seq = 283
current_ts = 181.530609
current_received_ts = 181.530304
current_seq = 284
count = 202
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.522171/283, current 181.530609/284: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.530609
last_received_ts = 181.530304
last_seq = 284
current_ts = 181.539047
current_received_ts = 181.538727
current_seq = 285
count = 203
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.530609/284, current 181.539047/285: elapsed=8431.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.539047
last_received_ts = 181.538727
last_seq = 285
current_ts = 181.547485
current_received_ts = 181.547226
current_seq = 286
count = 204
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.539047/285, current 181.547485/286: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.547485
last_received_ts = 181.547226
last_seq = 286
current_ts = 181.555923
current_received_ts = 181.555603
current_seq = 287
count = 205
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.547485/286, current 181.555923/287: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.555923
last_received_ts = 181.555603
last_seq = 287
current_ts = 181.564346
current_received_ts = 181.564056
current_seq = 288
count = 206
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.555923/287, current 181.564346/288: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.564346
last_received_ts = 181.564056
last_seq = 288
current_ts = 181.572800
current_received_ts = 181.572464
current_seq = 289
count = 207
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.564346/288, current 181.572800/289: elapsed=8443.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.572800
last_received_ts = 181.572464
last_seq = 289
current_ts = 181.581223
current_received_ts = 181.581070
current_seq = 290
count = 208
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.572800/289, current 181.581223/290: elapsed=8431.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.581223
last_received_ts = 181.581070
last_seq = 290
current_ts = 181.589661
current_received_ts = 181.589279
current_seq = 291
count = 209
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.581223/290, current 181.589661/291: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.589661
last_received_ts = 181.589279
last_seq = 291
current_ts = 181.598099
current_received_ts = 181.597778
current_seq = 292
count = 210
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.589661/291, current 181.598099/292: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.598099
last_received_ts = 181.597778
last_seq = 292
current_ts = 181.606537
current_received_ts = 181.606216
current_seq = 293
count = 211
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.598099/292, current 181.606537/293: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.606537
last_received_ts = 181.606216
last_seq = 293
current_ts = 181.614975
current_received_ts = 181.614670
current_seq = 294
count = 212
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.606537/293, current 181.614975/294: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.614975
last_received_ts = 181.614670
last_seq = 294
current_ts = 181.623413
current_received_ts = 181.623169
current_seq = 295
count = 213
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.614975/294, current 181.623413/295: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.623413
last_received_ts = 181.623169
last_seq = 295
current_ts = 181.631851
current_received_ts = 181.631622
current_seq = 296
count = 214
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.623413/295, current 181.631851/296: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.631851
last_received_ts = 181.631622
last_seq = 296
current_ts = 181.640289
current_received_ts = 181.639969
current_seq = 297
count = 215
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.631851/296, current 181.640289/297: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.640289
last_received_ts = 181.639969
last_seq = 297
current_ts = 181.648727
current_received_ts = 181.648407
current_seq = 298
count = 216
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.640289/297, current 181.648727/298: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.648727
last_received_ts = 181.648407
last_seq = 298
current_ts = 181.657166
current_received_ts = 181.656952
current_seq = 299
count = 217
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.648727/298, current 181.657166/299: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.657166
last_received_ts = 181.656952
last_seq = 299
current_ts = 181.665604
current_received_ts = 181.665298
current_seq = 300
count = 218
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.657166/299, current 181.665604/300: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.665604
last_received_ts = 181.665298
last_seq = 300
current_ts = 181.674042
current_received_ts = 181.673706
current_seq = 301
count = 219
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.665604/300, current 181.674042/301: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.674042
last_received_ts = 181.673706
last_seq = 301
current_ts = 181.682480
current_received_ts = 181.682175
current_seq = 302
count = 220
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.674042/301, current 181.682480/302: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.682480
last_received_ts = 181.682175
last_seq = 302
current_ts = 181.690903
current_received_ts = 181.690598
current_seq = 303
count = 221
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.682480/302, current 181.690903/303: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.690903
last_received_ts = 181.690598
last_seq = 303
current_ts = 181.699341
current_received_ts = 181.698990
current_seq = 304
count = 222
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.690903/303, current 181.699341/304: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.699341
last_received_ts = 181.698990
last_seq = 304
current_ts = 181.707779
current_received_ts = 181.707458
current_seq = 305
count = 223
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.699341/304, current 181.707779/305: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.707779
last_received_ts = 181.707458
last_seq = 305
current_ts = 181.716217
current_received_ts = 181.716064
current_seq = 306
count = 224
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.707779/305, current 181.716217/306: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.716217
last_received_ts = 181.716064
last_seq = 306
current_ts = 181.724655
current_received_ts = 181.724350
current_seq = 307
count = 225
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.716217/306, current 181.724655/307: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.724655
last_received_ts = 181.724350
last_seq = 307
current_ts = 181.733093
current_received_ts = 181.732895
current_seq = 308
count = 226
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.724655/307, current 181.733093/308: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.733093
last_received_ts = 181.732895
last_seq = 308
current_ts = 181.741531
current_received_ts = 181.741272
current_seq = 309
count = 227
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.733093/308, current 181.741531/309: elapsed=8443.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.741531
last_received_ts = 181.741272
last_seq = 309
current_ts = 181.749969
current_received_ts = 181.749786
current_seq = 310
count = 228
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.741531/309, current 181.749969/310: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.749969
last_received_ts = 181.749786
last_seq = 310
current_ts = 181.758392
current_received_ts = 181.758163
current_seq = 311
count = 229
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.749969/310, current 181.758392/311: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.758392
last_received_ts = 181.758163
last_seq = 311
current_ts = 181.766830
current_received_ts = 181.766617
current_seq = 312
count = 230
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.758392/311, current 181.766830/312: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.766830
last_received_ts = 181.766617
last_seq = 312
current_ts = 181.775269
current_received_ts = 181.775131
current_seq = 313
count = 231
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.766830/312, current 181.775269/313: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.775269
last_received_ts = 181.775131
last_seq = 313
current_ts = 181.783707
current_received_ts = 181.783478
current_seq = 314
count = 232
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.775269/313, current 181.783707/314: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.783707
last_received_ts = 181.783478
last_seq = 314
current_ts = 181.792145
current_received_ts = 181.791946
current_seq = 315
count = 233
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.783707/314, current 181.792145/315: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.792145
last_received_ts = 181.791946
last_seq = 315
current_ts = 181.800583
current_received_ts = 181.800354
current_seq = 316
count = 234
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.792145/315, current 181.800583/316: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.800583
last_received_ts = 181.800354
last_seq = 316
current_ts = 181.809021
current_received_ts = 181.808670
current_seq = 317
count = 235
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.800583/316, current 181.809021/317: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.809021
last_received_ts = 181.808670
last_seq = 317
current_ts = 181.817459
current_received_ts = 181.817200
current_seq = 318
count = 236
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.809021/317, current 181.817459/318: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.817459
last_received_ts = 181.817200
last_seq = 318
current_ts = 181.825897
current_received_ts = 181.825577
current_seq = 319
count = 237
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.817459/318, current 181.825897/319: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.825897
last_received_ts = 181.825577
last_seq = 319
current_ts = 181.834335
current_received_ts = 181.834122
current_seq = 320
count = 238
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.825897/319, current 181.834335/320: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.834335
last_received_ts = 181.834122
last_seq = 320
current_ts = 181.842773
current_received_ts = 181.842545
current_seq = 321
count = 239
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.834335/320, current 181.842773/321: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.842773
last_received_ts = 181.842545
last_seq = 321
current_ts = 181.851212
current_received_ts = 181.850845
current_seq = 322
count = 240
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.842773/321, current 181.851212/322: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.851212
last_received_ts = 181.850845
last_seq = 322
current_ts = 181.859650
current_received_ts = 181.859406
current_seq = 323
count = 241
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.851212/322, current 181.859650/323: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.859650
last_received_ts = 181.859406
last_seq = 323
current_ts = 181.868073
current_received_ts = 181.867813
current_seq = 324
count = 242
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.859650/323, current 181.868073/324: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.868073
last_received_ts = 181.867813
last_seq = 324
current_ts = 181.876526
current_received_ts = 181.876190
current_seq = 325
count = 243
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.868073/324, current 181.876526/325: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.876526
last_received_ts = 181.876190
last_seq = 325
current_ts = 181.884964
current_received_ts = 181.884613
current_seq = 326
count = 244
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.876526/325, current 181.884964/326: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.884964
last_received_ts = 181.884613
last_seq = 326
current_ts = 181.893387
current_received_ts = 181.893066
current_seq = 327
count = 245
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.884964/326, current 181.893387/327: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.893387
last_received_ts = 181.893066
last_seq = 327
current_ts = 181.901825
current_received_ts = 181.901474
current_seq = 328
count = 246
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.893387/327, current 181.901825/328: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.901825
last_received_ts = 181.901474
last_seq = 328
current_ts = 181.910263
current_received_ts = 181.909943
current_seq = 329
count = 247
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.901825/328, current 181.910263/329: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.910263
last_received_ts = 181.909943
last_seq = 329
current_ts = 181.918701
current_received_ts = 181.918381
current_seq = 330
count = 248
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.910263/329, current 181.918701/330: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.918701
last_received_ts = 181.918381
last_seq = 330
current_ts = 181.927139
current_received_ts = 181.926819
current_seq = 331
count = 249
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.918701/330, current 181.927139/331: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.927139
last_received_ts = 181.926819
last_seq = 331
current_ts = 181.935577
current_received_ts = 181.935349
current_seq = 332
count = 250
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.927139/331, current 181.935577/332: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.935577
last_received_ts = 181.935349
last_seq = 332
current_ts = 181.944016
current_received_ts = 181.943695
current_seq = 333
count = 251
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.935577/332, current 181.944016/333: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.944016
last_received_ts = 181.943695
last_seq = 333
current_ts = 181.952454
current_received_ts = 181.952209
current_seq = 334
count = 252
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.944016/333, current 181.952454/334: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.952454
last_received_ts = 181.952209
last_seq = 334
current_ts = 181.960876
current_received_ts = 181.960602
current_seq = 335
count = 253
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.952454/334, current 181.960876/335: elapsed=8431.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.960876
last_received_ts = 181.960602
last_seq = 335
current_ts = 181.969315
current_received_ts = 181.969009
current_seq = 336
count = 254
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.960876/335, current 181.969315/336: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.969315
last_received_ts = 181.969009
last_seq = 336
current_ts = 181.977753
current_received_ts = 181.977524
current_seq = 337
count = 255
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.969315/336, current 181.977753/337: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.977753
last_received_ts = 181.977524
last_seq = 337
current_ts = 181.986191
current_received_ts = 181.985855
current_seq = 338
count = 256
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.977753/337, current 181.986191/338: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.986191
last_received_ts = 181.985855
last_seq = 338
current_ts = 181.994629
current_received_ts = 181.994232
current_seq = 339
count = 257
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.986191/338, current 181.994629/339: elapsed=8442.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 181.994629
last_received_ts = 181.994232
last_seq = 339
current_ts = 182.003067
current_received_ts = 182.002747
current_seq = 340
count = 258
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 181.994629/339, current 182.003067/340: elapsed=8432.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.003067
last_received_ts = 182.002747
last_seq = 340
current_ts = 182.011505
current_received_ts = 182.011246
current_seq = 341
count = 259
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.003067/340, current 182.011505/341: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.011505
last_received_ts = 182.011246
last_seq = 341
current_ts = 182.019943
current_received_ts = 182.019684
current_seq = 342
count = 260
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.011505/341, current 182.019943/342: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.019943
last_received_ts = 182.019684
last_seq = 342
current_ts = 182.028381
current_received_ts = 182.028168
current_seq = 343
count = 261
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.019943/342, current 182.028381/343: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.028381
last_received_ts = 182.028168
last_seq = 343
current_ts = 182.036819
current_received_ts = 182.036545
current_seq = 344
count = 262
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.028381/343, current 182.036819/344: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.036819
last_received_ts = 182.036545
last_seq = 344
current_ts = 182.045258
current_received_ts = 182.044937
current_seq = 345
count = 263
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.036819/344, current 182.045258/345: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.045258
last_received_ts = 182.044937
last_seq = 345
current_ts = 182.053696
current_received_ts = 182.053375
current_seq = 346
count = 264
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.045258/345, current 182.053696/346: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.053696
last_received_ts = 182.053375
last_seq = 346
current_ts = 182.062119
current_received_ts = 182.061798
current_seq = 347
count = 265
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.053696/346, current 182.062119/347: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.062119
last_received_ts = 182.061798
last_seq = 347
current_ts = 182.070557
current_received_ts = 182.070236
current_seq = 348
count = 266
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.062119/347, current 182.070557/348: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.070557
last_received_ts = 182.070236
last_seq = 348
current_ts = 182.079010
current_received_ts = 182.078751
current_seq = 349
count = 267
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.070557/348, current 182.079010/349: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.079010
last_received_ts = 182.078751
last_seq = 349
current_ts = 182.087433
current_received_ts = 182.087204
current_seq = 350
count = 268
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.079010/349, current 182.087433/350: elapsed=8431.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.087433
last_received_ts = 182.087204
last_seq = 350
current_ts = 182.095871
current_received_ts = 182.095642
current_seq = 351
count = 269
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.087433/350, current 182.095871/351: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.095871
last_received_ts = 182.095642
last_seq = 351
current_ts = 182.104309
current_received_ts = 182.103973
current_seq = 352
count = 270
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.095871/351, current 182.104309/352: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.104309
last_received_ts = 182.103973
last_seq = 352
current_ts = 182.112747
current_received_ts = 182.112411
current_seq = 353
count = 271
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.104309/352, current 182.112747/353: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.112747
last_received_ts = 182.112411
last_seq = 353
current_ts = 182.121185
current_received_ts = 182.120850
current_seq = 354
count = 272
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.112747/353, current 182.121185/354: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.121185
last_received_ts = 182.120850
last_seq = 354
current_ts = 182.129623
current_received_ts = 182.129349
current_seq = 355
count = 273
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.121185/354, current 182.129623/355: elapsed=8432.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.129623
last_received_ts = 182.129349
last_seq = 355
current_ts = 182.138062
current_received_ts = 182.137848
current_seq = 356
count = 274
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.129623/355, current 182.138062/356: elapsed=8442.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.138062
last_received_ts = 182.137848
last_seq = 356
current_ts = 182.146500
current_received_ts = 182.146255
current_seq = 357
count = 275
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.138062/356, current 182.146500/357: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.146500
last_received_ts = 182.146255
last_seq = 357
current_ts = 182.154938
current_received_ts = 182.154602
current_seq = 358
count = 276
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.146500/357, current 182.154938/358: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.154938
last_received_ts = 182.154602
last_seq = 358
current_ts = 182.163361
current_received_ts = 182.163086
current_seq = 359
count = 277
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.154938/358, current 182.163361/359: elapsed=8432.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.163361
last_received_ts = 182.163086
last_seq = 359
current_ts = 182.171814
current_received_ts = 182.171570
current_seq = 360
count = 278
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.163361/359, current 182.171814/360: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.171814
last_received_ts = 182.171570
last_seq = 360
current_ts = 182.180237
current_received_ts = 182.180084
current_seq = 361
count = 279
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.171814/360, current 182.180237/361: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.180237
last_received_ts = 182.180084
last_seq = 361
current_ts = 182.188675
current_received_ts = 182.188339
current_seq = 362
count = 280
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.180237/361, current 182.188675/362: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.188675
last_received_ts = 182.188339
last_seq = 362
current_ts = 182.197113
current_received_ts = 182.196823
current_seq = 363
count = 281
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.188675/362, current 182.197113/363: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.197113
last_received_ts = 182.196823
last_seq = 363
current_ts = 182.205551
current_received_ts = 182.205246
current_seq = 364
count = 282
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.197113/363, current 182.205551/364: elapsed=8436.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.205551
last_received_ts = 182.205246
last_seq = 364
current_ts = 182.213989
current_received_ts = 182.213760
current_seq = 365
count = 283
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.205551/364, current 182.213989/365: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.213989
last_received_ts = 182.213760
last_seq = 365
current_ts = 182.222427
current_received_ts = 182.222153
current_seq = 366
count = 284
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.213989/365, current 182.222427/366: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.222427
last_received_ts = 182.222153
last_seq = 366
current_ts = 182.230865
current_received_ts = 182.230560
current_seq = 367
count = 285
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.222427/366, current 182.230865/367: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.230865
last_received_ts = 182.230560
last_seq = 367
current_ts = 182.239304
current_received_ts = 182.238998
current_seq = 368
count = 286
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.230865/367, current 182.239304/368: elapsed=8441.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.239304
last_received_ts = 182.238998
last_seq = 368
current_ts = 182.247742
current_received_ts = 182.247406
current_seq = 369
count = 287
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.239304/368, current 182.247742/369: elapsed=8432.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.247742
last_received_ts = 182.247406
last_seq = 369
current_ts = 182.256180
current_received_ts = 182.255844
current_seq = 370
count = 288
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.247742/369, current 182.256180/370: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.256180
last_received_ts = 182.255844
last_seq = 370
current_ts = 182.264603
current_received_ts = 182.264267
current_seq = 371
count = 289
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.256180/370, current 182.264603/371: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.264603
last_received_ts = 182.264267
last_seq = 371
current_ts = 182.273041
current_received_ts = 182.272720
current_seq = 372
count = 290
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.264603/371, current 182.273041/372: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.273041
last_received_ts = 182.272720
last_seq = 372
current_ts = 182.281479
current_received_ts = 182.281235
current_seq = 373
count = 291
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.273041/372, current 182.281479/373: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.281479
last_received_ts = 182.281235
last_seq = 373
current_ts = 182.289917
current_received_ts = 182.289597
current_seq = 374
count = 292
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.281479/373, current 182.289917/374: elapsed=8439.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.289917
last_received_ts = 182.289597
last_seq = 374
current_ts = 182.298355
current_received_ts = 182.298065
current_seq = 375
count = 293
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.289917/374, current 182.298355/375: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.298355
last_received_ts = 182.298065
last_seq = 375
current_ts = 182.306793
current_received_ts = 182.306549
current_seq = 376
count = 294
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.298355/375, current 182.306793/376: elapsed=8438.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.306793
last_received_ts = 182.306549
last_seq = 376
current_ts = 182.315231
current_received_ts = 182.315048
current_seq = 377
count = 295
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.306793/376, current 182.315231/377: elapsed=8433.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.315231
last_received_ts = 182.315048
last_seq = 377
current_ts = 182.323669
current_received_ts = 182.323425
current_seq = 378
count = 296
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.315231/377, current 182.323669/378: elapsed=8434.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.323669
last_received_ts = 182.323425
last_seq = 378
current_ts = 182.332108
current_received_ts = 182.331879
current_seq = 379
count = 297
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.323669/378, current 182.332108/379: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.332108
last_received_ts = 182.331879
last_seq = 379
current_ts = 182.340546
current_received_ts = 182.340256
current_seq = 380
count = 298
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.332108/379, current 182.340546/380: elapsed=8437.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.340546
last_received_ts = 182.340256
last_seq = 380
current_ts = 182.348984
current_received_ts = 182.348663
current_seq = 381
count = 299
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.340546/380, current 182.348984/381: elapsed=8440.0us expected=8466.9us +- 42.3us, error 0.3%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.348984
last_received_ts = 182.348663
last_seq = 381
current_ts = 182.357422
current_received_ts = 182.357101
current_seq = 382
count = 300
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.348984/381, current 182.357422/382: elapsed=8435.0us expected=8466.9us +- 42.3us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.357422
last_received_ts = 182.357101
last_seq = 382
current_ts = 182.365845
current_received_ts = 182.365524
current_seq = 383
count = 301
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.357422/382, current 182.365845/383: elapsed=8425.0us expected=8466.9us +- 42.3us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 182.365845
last_received_ts = 182.365524
last_seq = 383
current_ts = 182.374268
current_received_ts = 182.373947
current_seq = 384
count = 302
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 182.365845/383, current 182.374268/384: elapsed=8422.0us expected=8466.9us +- 42.3us, error 0.5%
(kms_flip:2198) DEBUG: inconsistent flip ts/seq: last 182.365845/383, current 182.374268/384: elapsed=8422.0us expected=8466.9us
(kms_flip:2198) DEBUG: expected 0, counted 302, encoder type 2
(kms_flip:2198) DEBUG: dropped frames, expected 0, counted 302, encoder type 2
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2198) igt_core-INFO: Stack trace:
(kms_flip:2198) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2198) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2198) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2198) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2198) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2198) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2198) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2198) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (5.988s)
Starting dynamic subtest: C-HDMI-A1
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.344818
last_received_ts = 192.344482
last_seq = 853
current_ts = 192.353180
current_received_ts = 192.352844
current_seq = 854
count = 775
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.344818/853, current 192.353180/854: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.353180
last_received_ts = 192.352844
last_seq = 854
current_ts = 192.361526
current_received_ts = 192.361298
current_seq = 855
count = 776
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.353180/854, current 192.361526/855: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.361526
last_received_ts = 192.361298
last_seq = 855
current_ts = 192.369904
current_received_ts = 192.369629
current_seq = 856
count = 777
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.361526/855, current 192.369904/856: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.369904
last_received_ts = 192.369629
last_seq = 856
current_ts = 192.378265
current_received_ts = 192.377945
current_seq = 857
count = 778
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.369904/856, current 192.378265/857: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.378265
last_received_ts = 192.377945
last_seq = 857
current_ts = 192.386627
current_received_ts = 192.386383
current_seq = 858
count = 779
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.378265/857, current 192.386627/858: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.386627
last_received_ts = 192.386383
last_seq = 858
current_ts = 192.394974
current_received_ts = 192.394653
current_seq = 859
count = 780
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.386627/858, current 192.394974/859: elapsed=8357.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.394974
last_received_ts = 192.394653
last_seq = 859
current_ts = 192.403336
current_received_ts = 192.403168
current_seq = 860
count = 781
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.394974/859, current 192.403336/860: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.403336
last_received_ts = 192.403168
last_seq = 860
current_ts = 192.411697
current_received_ts = 192.411407
current_seq = 861
count = 782
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.403336/860, current 192.411697/861: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.411697
last_received_ts = 192.411407
last_seq = 861
current_ts = 192.420074
current_received_ts = 192.419769
current_seq = 862
count = 783
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.411697/861, current 192.420074/862: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.420074
last_received_ts = 192.419769
last_seq = 862
current_ts = 192.428421
current_received_ts = 192.428085
current_seq = 863
count = 784
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.420074/862, current 192.428421/863: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.428421
last_received_ts = 192.428085
last_seq = 863
current_ts = 192.436798
current_received_ts = 192.436584
current_seq = 864
count = 785
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.428421/863, current 192.436798/864: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.436798
last_received_ts = 192.436584
last_seq = 864
current_ts = 192.445145
current_received_ts = 192.444824
current_seq = 865
count = 786
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.436798/864, current 192.445145/865: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.445145
last_received_ts = 192.444824
last_seq = 865
current_ts = 192.453506
current_received_ts = 192.453232
current_seq = 866
count = 787
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.445145/865, current 192.453506/866: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.453506
last_received_ts = 192.453232
last_seq = 866
current_ts = 192.461868
current_received_ts = 192.461594
current_seq = 867
count = 788
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.453506/866, current 192.461868/867: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.461868
last_received_ts = 192.461594
last_seq = 867
current_ts = 192.470230
current_received_ts = 192.469925
current_seq = 868
count = 789
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.461868/867, current 192.470230/868: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.470230
last_received_ts = 192.469925
last_seq = 868
current_ts = 192.478592
current_received_ts = 192.478256
current_seq = 869
count = 790
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.470230/868, current 192.478592/869: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.478592
last_received_ts = 192.478256
last_seq = 869
current_ts = 192.486954
current_received_ts = 192.486633
current_seq = 870
count = 791
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.478592/869, current 192.486954/870: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.486954
last_received_ts = 192.486633
last_seq = 870
current_ts = 192.495316
current_received_ts = 192.495071
current_seq = 871
count = 792
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.486954/870, current 192.495316/871: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.495316
last_received_ts = 192.495071
last_seq = 871
current_ts = 192.503677
current_received_ts = 192.503448
current_seq = 872
count = 793
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.495316/871, current 192.503677/872: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.503677
last_received_ts = 192.503448
last_seq = 872
current_ts = 192.512039
current_received_ts = 192.511841
current_seq = 873
count = 794
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.503677/872, current 192.512039/873: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.512039
last_received_ts = 192.511841
last_seq = 873
current_ts = 192.520401
current_received_ts = 192.520081
current_seq = 874
count = 795
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.512039/873, current 192.520401/874: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.520401
last_received_ts = 192.520081
last_seq = 874
current_ts = 192.528763
current_received_ts = 192.528503
current_seq = 875
count = 796
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.520401/874, current 192.528763/875: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.528763
last_received_ts = 192.528503
last_seq = 875
current_ts = 192.537125
current_received_ts = 192.536911
current_seq = 876
count = 797
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.528763/875, current 192.537125/876: elapsed=8367.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.537125
last_received_ts = 192.536911
last_seq = 876
current_ts = 192.545486
current_received_ts = 192.545197
current_seq = 877
count = 798
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.537125/876, current 192.545486/877: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.545486
last_received_ts = 192.545197
last_seq = 877
current_ts = 192.553848
current_received_ts = 192.553528
current_seq = 878
count = 799
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.545486/877, current 192.553848/878: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.553848
last_received_ts = 192.553528
last_seq = 878
current_ts = 192.562210
current_received_ts = 192.561874
current_seq = 879
count = 800
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.553848/878, current 192.562210/879: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.562210
last_received_ts = 192.561874
last_seq = 879
current_ts = 192.570572
current_received_ts = 192.570251
current_seq = 880
count = 801
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.562210/879, current 192.570572/880: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.570572
last_received_ts = 192.570251
last_seq = 880
current_ts = 192.578934
current_received_ts = 192.578613
current_seq = 881
count = 802
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.570572/880, current 192.578934/881: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.578934
last_received_ts = 192.578613
last_seq = 881
current_ts = 192.587296
current_received_ts = 192.586960
current_seq = 882
count = 803
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.578934/881, current 192.587296/882: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.587296
last_received_ts = 192.586960
last_seq = 882
current_ts = 192.595657
current_received_ts = 192.595322
current_seq = 883
count = 804
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.587296/882, current 192.595657/883: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.595657
last_received_ts = 192.595322
last_seq = 883
current_ts = 192.604019
current_received_ts = 192.603775
current_seq = 884
count = 805
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.595657/883, current 192.604019/884: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.604019
last_received_ts = 192.603775
last_seq = 884
current_ts = 192.612381
current_received_ts = 192.612061
current_seq = 885
count = 806
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.604019/884, current 192.612381/885: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.612381
last_received_ts = 192.612061
last_seq = 885
current_ts = 192.620743
current_received_ts = 192.620377
current_seq = 886
count = 807
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.612381/885, current 192.620743/886: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.620743
last_received_ts = 192.620377
last_seq = 886
current_ts = 192.629105
current_received_ts = 192.628830
current_seq = 887
count = 808
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.620743/886, current 192.629105/887: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.629105
last_received_ts = 192.628830
last_seq = 887
current_ts = 192.637466
current_received_ts = 192.637192
current_seq = 888
count = 809
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.629105/887, current 192.637466/888: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.637466
last_received_ts = 192.637192
last_seq = 888
current_ts = 192.645828
current_received_ts = 192.645508
current_seq = 889
count = 810
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.637466/888, current 192.645828/889: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.645828
last_received_ts = 192.645508
last_seq = 889
current_ts = 192.654190
current_received_ts = 192.653854
current_seq = 890
count = 811
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.645828/889, current 192.654190/890: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.654190
last_received_ts = 192.653854
last_seq = 890
current_ts = 192.662537
current_received_ts = 192.662277
current_seq = 891
count = 812
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.654190/890, current 192.662537/891: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.662537
last_received_ts = 192.662277
last_seq = 891
current_ts = 192.670898
current_received_ts = 192.670654
current_seq = 892
count = 813
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.662537/891, current 192.670898/892: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.670898
last_received_ts = 192.670654
last_seq = 892
current_ts = 192.679276
current_received_ts = 192.679123
current_seq = 893
count = 814
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.670898/892, current 192.679276/893: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.679276
last_received_ts = 192.679123
last_seq = 893
current_ts = 192.687637
current_received_ts = 192.687332
current_seq = 894
count = 815
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.679276/893, current 192.687637/894: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.687637
last_received_ts = 192.687332
last_seq = 894
current_ts = 192.695984
current_received_ts = 192.695755
current_seq = 895
count = 816
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.687637/894, current 192.695984/895: elapsed=8357.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.695984
last_received_ts = 192.695755
last_seq = 895
current_ts = 192.704346
current_received_ts = 192.704147
current_seq = 896
count = 817
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.695984/895, current 192.704346/896: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.704346
last_received_ts = 192.704147
last_seq = 896
current_ts = 192.712708
current_received_ts = 192.712479
current_seq = 897
count = 818
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.704346/896, current 192.712708/897: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.712708
last_received_ts = 192.712479
last_seq = 897
current_ts = 192.721069
current_received_ts = 192.720840
current_seq = 898
count = 819
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.712708/897, current 192.721069/898: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.721069
last_received_ts = 192.720840
last_seq = 898
current_ts = 192.729431
current_received_ts = 192.729126
current_seq = 899
count = 820
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.721069/898, current 192.729431/899: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.729431
last_received_ts = 192.729126
last_seq = 899
current_ts = 192.737793
current_received_ts = 192.737534
current_seq = 900
count = 821
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.729431/899, current 192.737793/900: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.737793
last_received_ts = 192.737534
last_seq = 900
current_ts = 192.746155
current_received_ts = 192.745850
current_seq = 901
count = 822
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.737793/900, current 192.746155/901: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.746155
last_received_ts = 192.745850
last_seq = 901
current_ts = 192.754517
current_received_ts = 192.754272
current_seq = 902
count = 823
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.746155/901, current 192.754517/902: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.754517
last_received_ts = 192.754272
last_seq = 902
current_ts = 192.762878
current_received_ts = 192.762558
current_seq = 903
count = 824
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.754517/902, current 192.762878/903: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.762878
last_received_ts = 192.762558
last_seq = 903
current_ts = 192.771240
current_received_ts = 192.770935
current_seq = 904
count = 825
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.762878/903, current 192.771240/904: elapsed=8357.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.771240
last_received_ts = 192.770935
last_seq = 904
current_ts = 192.779602
current_received_ts = 192.779419
current_seq = 905
count = 826
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.771240/904, current 192.779602/905: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.779602
last_received_ts = 192.779419
last_seq = 905
current_ts = 192.787964
current_received_ts = 192.787689
current_seq = 906
count = 827
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.779602/905, current 192.787964/906: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.787964
last_received_ts = 192.787689
last_seq = 906
current_ts = 192.796326
current_received_ts = 192.796036
current_seq = 907
count = 828
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.787964/906, current 192.796326/907: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.796326
last_received_ts = 192.796036
last_seq = 907
current_ts = 192.804688
current_received_ts = 192.804443
current_seq = 908
count = 829
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.796326/907, current 192.804688/908: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.804688
last_received_ts = 192.804443
last_seq = 908
current_ts = 192.813049
current_received_ts = 192.812836
current_seq = 909
count = 830
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.804688/908, current 192.813049/909: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.813049
last_received_ts = 192.812836
last_seq = 909
current_ts = 192.821411
current_received_ts = 192.821136
current_seq = 910
count = 831
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.813049/909, current 192.821411/910: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.821411
last_received_ts = 192.821136
last_seq = 910
current_ts = 192.829773
current_received_ts = 192.829590
current_seq = 911
count = 832
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.821411/910, current 192.829773/911: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.829773
last_received_ts = 192.829590
last_seq = 911
current_ts = 192.838135
current_received_ts = 192.837814
current_seq = 912
count = 833
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.829773/911, current 192.838135/912: elapsed=8355.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.838135
last_received_ts = 192.837814
last_seq = 912
current_ts = 192.846497
current_received_ts = 192.846237
current_seq = 913
count = 834
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.838135/912, current 192.846497/913: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.846497
last_received_ts = 192.846237
last_seq = 913
current_ts = 192.854858
current_received_ts = 192.854538
current_seq = 914
count = 835
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.846497/913, current 192.854858/914: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.854858
last_received_ts = 192.854538
last_seq = 914
current_ts = 192.863220
current_received_ts = 192.863083
current_seq = 915
count = 836
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.854858/914, current 192.863220/915: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.863220
last_received_ts = 192.863083
last_seq = 915
current_ts = 192.871582
current_received_ts = 192.871323
current_seq = 916
count = 837
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.863220/915, current 192.871582/916: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.871582
last_received_ts = 192.871323
last_seq = 916
current_ts = 192.879944
current_received_ts = 192.879623
current_seq = 917
count = 838
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.871582/916, current 192.879944/917: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.879944
last_received_ts = 192.879623
last_seq = 917
current_ts = 192.888306
current_received_ts = 192.887970
current_seq = 918
count = 839
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.879944/917, current 192.888306/918: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.888306
last_received_ts = 192.887970
last_seq = 918
current_ts = 192.896652
current_received_ts = 192.896347
current_seq = 919
count = 840
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.888306/918, current 192.896652/919: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.896652
last_received_ts = 192.896347
last_seq = 919
current_ts = 192.905029
current_received_ts = 192.904739
current_seq = 920
count = 841
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.896652/919, current 192.905029/920: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.905029
last_received_ts = 192.904739
last_seq = 920
current_ts = 192.913391
current_received_ts = 192.913177
current_seq = 921
count = 842
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.905029/920, current 192.913391/921: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.913391
last_received_ts = 192.913177
last_seq = 921
current_ts = 192.921738
current_received_ts = 192.921494
current_seq = 922
count = 843
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.913391/921, current 192.921738/922: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.921738
last_received_ts = 192.921494
last_seq = 922
current_ts = 192.930099
current_received_ts = 192.929932
current_seq = 923
count = 844
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.921738/922, current 192.930099/923: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.930099
last_received_ts = 192.929932
last_seq = 923
current_ts = 192.938461
current_received_ts = 192.938187
current_seq = 924
count = 845
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.930099/923, current 192.938461/924: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.938461
last_received_ts = 192.938187
last_seq = 924
current_ts = 192.946823
current_received_ts = 192.946548
current_seq = 925
count = 846
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.938461/924, current 192.946823/925: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.946823
last_received_ts = 192.946548
last_seq = 925
current_ts = 192.955185
current_received_ts = 192.955063
current_seq = 926
count = 847
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.946823/925, current 192.955185/926: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.955185
last_received_ts = 192.955063
last_seq = 926
current_ts = 192.963547
current_received_ts = 192.963242
current_seq = 927
count = 848
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.955185/926, current 192.963547/927: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.963547
last_received_ts = 192.963242
last_seq = 927
current_ts = 192.971909
current_received_ts = 192.971588
current_seq = 928
count = 849
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.963547/927, current 192.971909/928: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.971909
last_received_ts = 192.971588
last_seq = 928
current_ts = 192.980270
current_received_ts = 192.979965
current_seq = 929
count = 850
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.971909/928, current 192.980270/929: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.980270
last_received_ts = 192.979965
last_seq = 929
current_ts = 192.988632
current_received_ts = 192.988327
current_seq = 930
count = 851
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.980270/929, current 192.988632/930: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.988632
last_received_ts = 192.988327
last_seq = 930
current_ts = 192.996994
current_received_ts = 192.996674
current_seq = 931
count = 852
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.988632/930, current 192.996994/931: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 192.996994
last_received_ts = 192.996674
last_seq = 931
current_ts = 193.005356
current_received_ts = 193.005157
current_seq = 932
count = 853
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 192.996994/931, current 193.005356/932: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.005356
last_received_ts = 193.005157
last_seq = 932
current_ts = 193.013718
current_received_ts = 193.013458
current_seq = 933
count = 854
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.005356/932, current 193.013718/933: elapsed=8357.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.013718
last_received_ts = 193.013458
last_seq = 933
current_ts = 193.022079
current_received_ts = 193.021744
current_seq = 934
count = 855
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.013718/933, current 193.022079/934: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.022079
last_received_ts = 193.021744
last_seq = 934
current_ts = 193.030441
current_received_ts = 193.030182
current_seq = 935
count = 856
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.022079/934, current 193.030441/935: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.030441
last_received_ts = 193.030182
last_seq = 935
current_ts = 193.038803
current_received_ts = 193.038498
current_seq = 936
count = 857
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.030441/935, current 193.038803/936: elapsed=8366.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.038803
last_received_ts = 193.038498
last_seq = 936
current_ts = 193.047165
current_received_ts = 193.046844
current_seq = 937
count = 858
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.038803/936, current 193.047165/937: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.047165
last_received_ts = 193.046844
last_seq = 937
current_ts = 193.055527
current_received_ts = 193.055206
current_seq = 938
count = 859
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.047165/937, current 193.055527/938: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.055527
last_received_ts = 193.055206
last_seq = 938
current_ts = 193.063889
current_received_ts = 193.063568
current_seq = 939
count = 860
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.055527/938, current 193.063889/939: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.063889
last_received_ts = 193.063568
last_seq = 939
current_ts = 193.072250
current_received_ts = 193.071976
current_seq = 940
count = 861
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.063889/939, current 193.072250/940: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.072250
last_received_ts = 193.071976
last_seq = 940
current_ts = 193.080612
current_received_ts = 193.080368
current_seq = 941
count = 862
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.072250/940, current 193.080612/941: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.080612
last_received_ts = 193.080368
last_seq = 941
current_ts = 193.088974
current_received_ts = 193.088654
current_seq = 942
count = 863
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.080612/941, current 193.088974/942: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.088974
last_received_ts = 193.088654
last_seq = 942
current_ts = 193.097336
current_received_ts = 193.097168
current_seq = 943
count = 864
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.088974/942, current 193.097336/943: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.097336
last_received_ts = 193.097168
last_seq = 943
current_ts = 193.105698
current_received_ts = 193.105377
current_seq = 944
count = 865
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.097336/943, current 193.105698/944: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.105698
last_received_ts = 193.105377
last_seq = 944
current_ts = 193.114059
current_received_ts = 193.113724
current_seq = 945
count = 866
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.105698/944, current 193.114059/945: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.114059
last_received_ts = 193.113724
last_seq = 945
current_ts = 193.122421
current_received_ts = 193.122101
current_seq = 946
count = 867
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.114059/945, current 193.122421/946: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.122421
last_received_ts = 193.122101
last_seq = 946
current_ts = 193.130783
current_received_ts = 193.130447
current_seq = 947
count = 868
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.122421/946, current 193.130783/947: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.130783
last_received_ts = 193.130447
last_seq = 947
current_ts = 193.139130
current_received_ts = 193.138992
current_seq = 948
count = 869
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.130783/947, current 193.139130/948: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.139130
last_received_ts = 193.138992
last_seq = 948
current_ts = 193.147491
current_received_ts = 193.147171
current_seq = 949
count = 870
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.139130/948, current 193.147491/949: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.147491
last_received_ts = 193.147171
last_seq = 949
current_ts = 193.155853
current_received_ts = 193.155502
current_seq = 950
count = 871
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.147491/949, current 193.155853/950: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.155853
last_received_ts = 193.155502
last_seq = 950
current_ts = 193.164215
current_received_ts = 193.163895
current_seq = 951
count = 872
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.155853/950, current 193.164215/951: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.164215
last_received_ts = 193.163895
last_seq = 951
current_ts = 193.172592
current_received_ts = 193.172256
current_seq = 952
count = 873
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.164215/951, current 193.172592/952: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.172592
last_received_ts = 193.172256
last_seq = 952
current_ts = 193.180954
current_received_ts = 193.180603
current_seq = 953
count = 874
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.172592/952, current 193.180954/953: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.180954
last_received_ts = 193.180603
last_seq = 953
current_ts = 193.189301
current_received_ts = 193.189178
current_seq = 954
count = 875
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.180954/953, current 193.189301/954: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.189301
last_received_ts = 193.189178
last_seq = 954
current_ts = 193.197662
current_received_ts = 193.197342
current_seq = 955
count = 876
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.189301/954, current 193.197662/955: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.197662
last_received_ts = 193.197342
last_seq = 955
current_ts = 193.206024
current_received_ts = 193.205750
current_seq = 956
count = 877
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.197662/955, current 193.206024/956: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.206024
last_received_ts = 193.205750
last_seq = 956
current_ts = 193.214386
current_received_ts = 193.214081
current_seq = 957
count = 878
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.206024/956, current 193.214386/957: elapsed=8364.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.214386
last_received_ts = 193.214081
last_seq = 957
current_ts = 193.222748
current_received_ts = 193.222443
current_seq = 958
count = 879
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.214386/957, current 193.222748/958: elapsed=8357.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.222748
last_received_ts = 193.222443
last_seq = 958
current_ts = 193.231110
current_received_ts = 193.230804
current_seq = 959
count = 880
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.222748/958, current 193.231110/959: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.231110
last_received_ts = 193.230804
last_seq = 959
current_ts = 193.239471
current_received_ts = 193.239212
current_seq = 960
count = 881
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.231110/959, current 193.239471/960: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.239471
last_received_ts = 193.239212
last_seq = 960
current_ts = 193.247833
current_received_ts = 193.247498
current_seq = 961
count = 882
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.239471/960, current 193.247833/961: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.247833
last_received_ts = 193.247498
last_seq = 961
current_ts = 193.256195
current_received_ts = 193.255890
current_seq = 962
count = 883
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.247833/961, current 193.256195/962: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.256195
last_received_ts = 193.255890
last_seq = 962
current_ts = 193.264557
current_received_ts = 193.264313
current_seq = 963
count = 884
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.256195/962, current 193.264557/963: elapsed=8365.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.264557
last_received_ts = 193.264313
last_seq = 963
current_ts = 193.272919
current_received_ts = 193.272644
current_seq = 964
count = 885
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.264557/963, current 193.272919/964: elapsed=8359.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.272919
last_received_ts = 193.272644
last_seq = 964
current_ts = 193.281281
current_received_ts = 193.280960
current_seq = 965
count = 886
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.272919/964, current 193.281281/965: elapsed=8363.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.281281
last_received_ts = 193.280960
last_seq = 965
current_ts = 193.289642
current_received_ts = 193.289398
current_seq = 966
count = 887
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.281281/965, current 193.289642/966: elapsed=8356.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.289642
last_received_ts = 193.289398
last_seq = 966
current_ts = 193.298004
current_received_ts = 193.297699
current_seq = 967
count = 888
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.289642/966, current 193.298004/967: elapsed=8367.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.298004
last_received_ts = 193.297699
last_seq = 967
current_ts = 193.306366
current_received_ts = 193.306061
current_seq = 968
count = 889
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.298004/967, current 193.306366/968: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.306366
last_received_ts = 193.306061
last_seq = 968
current_ts = 193.314728
current_received_ts = 193.314484
current_seq = 969
count = 890
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.306366/968, current 193.314728/969: elapsed=8362.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.314728
last_received_ts = 193.314484
last_seq = 969
current_ts = 193.323090
current_received_ts = 193.322769
current_seq = 970
count = 891
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.314728/969, current 193.323090/970: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.323090
last_received_ts = 193.322769
last_seq = 970
current_ts = 193.331451
current_received_ts = 193.331192
current_seq = 971
count = 892
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.323090/970, current 193.331451/971: elapsed=8360.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.331451
last_received_ts = 193.331192
last_seq = 971
current_ts = 193.339813
current_received_ts = 193.339493
current_seq = 972
count = 893
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.331451/971, current 193.339813/972: elapsed=8358.0us expected=8396.4us +- 42.0us, error 0.5%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.339813
last_received_ts = 193.339493
last_seq = 972
current_ts = 193.348175
current_received_ts = 193.348053
current_seq = 973
count = 894
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.339813/972, current 193.348175/973: elapsed=8361.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: name = flip
last_ts = 193.348175
last_received_ts = 193.348053
last_seq = 973
current_ts = 193.356537
current_received_ts = 193.356277
current_seq = 974
count = 895
seq_step = 1
(kms_flip:2198) DEBUG: flip ts/seq: last 193.348175/973, current 193.356537/974: elapsed=8367.0us expected=8396.4us +- 42.0us, error 0.4%
(kms_flip:2198) DEBUG: expected 893, counted 896, encoder type 2
(kms_flip:2198) DEBUG: dropped frames, expected 893, counted 896, encoder type 2
(kms_flip:2198) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2198) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2198) igt_core-INFO: Stack trace:
(kms_flip:2198) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2198) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2198) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2198) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2198) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2198) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2198) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2198) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (10.925s)
Starting dynamic subtest: D-HDMI-A1
Dynamic subtest D-HDMI-A1: SUCCESS (7.830s)
Subtest plain-flip-ts-check: FAIL (28.251s)