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

shard-dg2-432

IGT-Version: 1.30-g40b32b434 (x86_64) (Linux: 6.14.0-rc5-xe+ x86_64)

Using IGT_SRANDOM=1741346878 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17368.2us +- 5.624us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 17368us +- 5.624us, difference 701.5us (124.7 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (3.921s)
Starting dynamic subtest: B-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17081.7us +- 9.185us accuracy 0.16%
vblank interval differs from modeline! expected 16666.7us, measured 17082us +- 9.185us, difference 415.0us (45.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A2: FAIL (4.833s)
Starting dynamic subtest: C-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16883.8us +- 5.648us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16884us +- 5.648us, difference 217.1us (38.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A2: FAIL (7.246s)
Starting dynamic subtest: D-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16757.3us +- 5.848us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16757us +- 5.848us, difference 90.6us (15.5 sigma)
Dynamic subtest D-HDMI-A2: SUCCESS (4.254s)
Starting dynamic subtest: A-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16720.7us +- 9.393us accuracy 0.17%
vblank interval differs from modeline! expected 16666.7us, measured 16721us +- 9.393us, difference 54.0us (5.8 sigma)
Dynamic subtest A-DP2: SUCCESS (4.291s)
Starting dynamic subtest: B-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16700.2us +- 6.181us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16700us +- 6.181us, difference 33.6us (5.4 sigma)
Dynamic subtest B-DP2: SUCCESS (4.280s)
Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16684.6us +- 8.484us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 16685us +- 8.484us, difference 18.0us (2.1 sigma)
Dynamic subtest C-DP2: SUCCESS (4.255s)
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16682.3us +- 4.254us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16682us +- 4.254us, difference 15.6us (3.7 sigma)
Dynamic subtest D-DP2: SUCCESS (4.249s)
Subtest plain-flip-ts-check: FAIL (37.349s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3849) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3849) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe76df0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe76df0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afebaa70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afebaa70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afebaa70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afebaa70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe84300, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe84300, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3849) DEBUG: No stale events found
(kms_flip:3849) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3849) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3849) INFO: Expected frametime: 16667us; measured 17368.2us +- 5.624us accuracy 0.10%
(kms_flip:3849) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17368us +- 5.624us, difference 701.5us (124.7 sigma)
(kms_flip:3849) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 168.212784
current_received_ts = 168.212189
current_seq = 5308
count = 0
seq_step = 1
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.212784
last_received_ts = 168.212189
last_seq = 5308
current_ts = 168.230164
current_received_ts = 168.229752
current_seq = 5309
count = 1
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.212784/5308, current 168.230164/5309: elapsed=17375.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.230164
last_received_ts = 168.229752
last_seq = 5309
current_ts = 168.247543
current_received_ts = 168.247116
current_seq = 5310
count = 2
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.230164/5309, current 168.247543/5310: elapsed=17372.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.247543
last_received_ts = 168.247116
last_seq = 5310
current_ts = 168.264893
current_received_ts = 168.264481
current_seq = 5311
count = 3
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.247543/5310, current 168.264893/5311: elapsed=17362.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.264893
last_received_ts = 168.264481
last_seq = 5311
current_ts = 168.282272
current_received_ts = 168.281830
current_seq = 5312
count = 4
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.264893/5311, current 168.282272/5312: elapsed=17378.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.282272
last_received_ts = 168.281830
last_seq = 5312
current_ts = 168.299652
current_received_ts = 168.299164
current_seq = 5313
count = 5
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.282272/5312, current 168.299652/5313: elapsed=17371.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.299652
last_received_ts = 168.299164
last_seq = 5313
current_ts = 168.317017
current_received_ts = 168.316467
current_seq = 5314
count = 6
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.299652/5313, current 168.317017/5314: elapsed=17369.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.317017
last_received_ts = 168.316467
last_seq = 5314
current_ts = 168.334381
current_received_ts = 168.333832
current_seq = 5315
count = 7
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.317017/5314, current 168.334381/5315: elapsed=17369.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.334381
last_received_ts = 168.333832
last_seq = 5315
current_ts = 168.351746
current_received_ts = 168.351212
current_seq = 5316
count = 8
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.334381/5315, current 168.351746/5316: elapsed=17356.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.351746
last_received_ts = 168.351212
last_seq = 5316
current_ts = 168.369110
current_received_ts = 168.368576
current_seq = 5317
count = 9
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.351746/5316, current 168.369110/5317: elapsed=17367.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.369110
last_received_ts = 168.368576
last_seq = 5317
current_ts = 168.386490
current_received_ts = 168.385941
current_seq = 5318
count = 10
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.369110/5317, current 168.386490/5318: elapsed=17377.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.386490
last_received_ts = 168.385941
last_seq = 5318
current_ts = 168.403854
current_received_ts = 168.403305
current_seq = 5319
count = 11
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.386490/5318, current 168.403854/5319: elapsed=17362.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.403854
last_received_ts = 168.403305
last_seq = 5319
current_ts = 168.421219
current_received_ts = 168.420670
current_seq = 5320
count = 12
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.403854/5319, current 168.421219/5320: elapsed=17366.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.421219
last_received_ts = 168.420670
last_seq = 5320
current_ts = 168.438599
current_received_ts = 168.438080
current_seq = 5321
count = 13
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.421219/5320, current 168.438599/5321: elapsed=17379.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.438599
last_received_ts = 168.438080
last_seq = 5321
current_ts = 168.455948
current_received_ts = 168.455414
current_seq = 5322
count = 14
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.438599/5321, current 168.455948/5322: elapsed=17359.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.455948
last_received_ts = 168.455414
last_seq = 5322
current_ts = 168.473328
current_received_ts = 168.472778
current_seq = 5323
count = 15
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.455948/5322, current 168.473328/5323: elapsed=17382.0us expected=17368.2us +- 86.8us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.473328
last_received_ts = 168.472778
last_seq = 5323
current_ts = 168.490692
current_received_ts = 168.490158
current_seq = 5324
count = 16
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.473328/5323, current 168.490692/5324: elapsed=17362.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.490692
last_received_ts = 168.490158
last_seq = 5324
current_ts = 168.508057
current_received_ts = 168.507523
current_seq = 5325
count = 17
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.490692/5324, current 168.508057/5325: elapsed=17362.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.508057
last_received_ts = 168.507523
last_seq = 5325
current_ts = 168.525421
current_received_ts = 168.524887
current_seq = 5326
count = 18
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.508057/5325, current 168.525421/5326: elapsed=17362.0us expected=17368.2us +- 86.8us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.525421
last_received_ts = 168.524887
last_seq = 5326
current_ts = 168.542709
current_received_ts = 168.542160
current_seq = 5327
count = 19
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.525421/5326, current 168.542709/5327: elapsed=17284.0us expected=17368.2us +- 86.8us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.542709
last_received_ts = 168.542160
last_seq = 5327
current_ts = 168.559998
current_received_ts = 168.559464
current_seq = 5328
count = 20
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.542709/5327, current 168.559998/5328: elapsed=17288.0us expected=17368.2us +- 86.8us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.559998
last_received_ts = 168.559464
last_seq = 5328
current_ts = 168.577271
current_received_ts = 168.576721
current_seq = 5329
count = 21
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.559998/5328, current 168.577271/5329: elapsed=17286.0us expected=17368.2us +- 86.8us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 168.577271
last_received_ts = 168.576721
last_seq = 5329
current_ts = 168.594543
current_received_ts = 168.594009
current_seq = 5330
count = 22
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 168.577271/5329, current 168.594543/5330: elapsed=17269.0us expected=17368.2us +- 86.8us, error 0.6%
(kms_flip:3849) DEBUG: inconsistent flip ts/seq: last 168.577271/5329, current 168.594543/5330: elapsed=17269.0us expected=17368.2us
(kms_flip:3849) DEBUG: expected 0, counted 22, encoder type 2
(kms_flip:3849) DEBUG: dropped frames, expected 0, counted 22, encoder type 2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3849) igt_core-INFO: Stack trace:
(kms_flip:3849) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3849) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3849) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3849) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3849) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3849) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3849) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3849) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (3.921s)
Starting dynamic subtest: B-HDMI-A2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:3849) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3849) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:3849) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe8c910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418afe8c910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) intel_allocator_simple-DEBUG: <ial: 0x6418aff12960, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3849) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3849) DEBUG: No stale events found
(kms_flip:3849) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3849) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3849) INFO: Expected frametime: 16667us; measured 17081.7us +- 9.185us accuracy 0.16%
(kms_flip:3849) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17082us +- 9.185us, difference 415.0us (45.2 sigma)
(kms_flip:3849) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 172.201965
current_received_ts = 172.201553
current_seq = 3745
count = 0
seq_step = 1
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.201965
last_received_ts = 172.201553
last_seq = 3745
current_ts = 172.219055
current_received_ts = 172.218613
current_seq = 3746
count = 1
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.201965/3745, current 172.219055/3746: elapsed=17092.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.219055
last_received_ts = 172.218613
last_seq = 3746
current_ts = 172.236115
current_received_ts = 172.235641
current_seq = 3747
count = 2
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.219055/3746, current 172.236115/3747: elapsed=17070.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.236115
last_received_ts = 172.235641
last_seq = 3747
current_ts = 172.253204
current_received_ts = 172.252716
current_seq = 3748
count = 3
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.236115/3747, current 172.253204/3748: elapsed=17084.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.253204
last_received_ts = 172.252716
last_seq = 3748
current_ts = 172.270279
current_received_ts = 172.269760
current_seq = 3749
count = 4
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.253204/3748, current 172.270279/3749: elapsed=17081.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.270279
last_received_ts = 172.269760
last_seq = 3749
current_ts = 172.287369
current_received_ts = 172.286835
current_seq = 3750
count = 5
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.270279/3749, current 172.287369/3750: elapsed=17080.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.287369
last_received_ts = 172.286835
last_seq = 3750
current_ts = 172.304459
current_received_ts = 172.303925
current_seq = 3751
count = 6
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.287369/3750, current 172.304459/3751: elapsed=17088.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.304459
last_received_ts = 172.303925
last_seq = 3751
current_ts = 172.321533
current_received_ts = 172.320999
current_seq = 3752
count = 7
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.304459/3751, current 172.321533/3752: elapsed=17079.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.321533
last_received_ts = 172.320999
last_seq = 3752
current_ts = 172.338608
current_received_ts = 172.338074
current_seq = 3753
count = 8
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.321533/3752, current 172.338608/3753: elapsed=17079.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.338608
last_received_ts = 172.338074
last_seq = 3753
current_ts = 172.355698
current_received_ts = 172.355164
current_seq = 3754
count = 9
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.338608/3753, current 172.355698/3754: elapsed=17083.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.355698
last_received_ts = 172.355164
last_seq = 3754
current_ts = 172.372772
current_received_ts = 172.372238
current_seq = 3755
count = 10
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.355698/3754, current 172.372772/3755: elapsed=17083.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.372772
last_received_ts = 172.372238
last_seq = 3755
current_ts = 172.389862
current_received_ts = 172.389328
current_seq = 3756
count = 11
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.372772/3755, current 172.389862/3756: elapsed=17088.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.389862
last_received_ts = 172.389328
last_seq = 3756
current_ts = 172.406937
current_received_ts = 172.406403
current_seq = 3757
count = 12
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.389862/3756, current 172.406937/3757: elapsed=17075.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.406937
last_received_ts = 172.406403
last_seq = 3757
current_ts = 172.424042
current_received_ts = 172.423477
current_seq = 3758
count = 13
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.406937/3757, current 172.424042/3758: elapsed=17096.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.424042
last_received_ts = 172.423477
last_seq = 3758
current_ts = 172.441116
current_received_ts = 172.440567
current_seq = 3759
count = 14
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.424042/3758, current 172.441116/3759: elapsed=17077.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.441116
last_received_ts = 172.440567
last_seq = 3759
current_ts = 172.458191
current_received_ts = 172.457642
current_seq = 3760
count = 15
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.441116/3759, current 172.458191/3760: elapsed=17073.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.458191
last_received_ts = 172.457642
last_seq = 3760
current_ts = 172.475281
current_received_ts = 172.474731
current_seq = 3761
count = 16
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.458191/3760, current 172.475281/3761: elapsed=17096.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.475281
last_received_ts = 172.474731
last_seq = 3761
current_ts = 172.492355
current_received_ts = 172.491806
current_seq = 3762
count = 17
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.475281/3761, current 172.492355/3762: elapsed=17067.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.492355
last_received_ts = 172.491806
last_seq = 3762
current_ts = 172.509430
current_received_ts = 172.508896
current_seq = 3763
count = 18
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.492355/3762, current 172.509430/3763: elapsed=17085.0us expected=17081.7us +- 85.4us, error 0.0%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.509430
last_received_ts = 172.508896
last_seq = 3763
current_ts = 172.526505
current_received_ts = 172.525970
current_seq = 3764
count = 19
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.509430/3763, current 172.526505/3764: elapsed=17068.0us expected=17081.7us +- 85.4us, error 0.1%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.526505
last_received_ts = 172.525970
last_seq = 3764
current_ts = 172.543549
current_received_ts = 172.542999
current_seq = 3765
count = 20
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.526505/3764, current 172.543549/3765: elapsed=17046.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.543549
last_received_ts = 172.542999
last_seq = 3765
current_ts = 172.560577
current_received_ts = 172.560059
current_seq = 3766
count = 21
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.543549/3765, current 172.560577/3766: elapsed=17022.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.560577
last_received_ts = 172.560059
last_seq = 3766
current_ts = 172.577606
current_received_ts = 172.577072
current_seq = 3767
count = 22
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.560577/3766, current 172.577606/3767: elapsed=17035.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.577606
last_received_ts = 172.577072
last_seq = 3767
current_ts = 172.594635
current_received_ts = 172.594101
current_seq = 3768
count = 23
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.577606/3767, current 172.594635/3768: elapsed=17034.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.594635
last_received_ts = 172.594101
last_seq = 3768
current_ts = 172.611679
current_received_ts = 172.611130
current_seq = 3769
count = 24
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.594635/3768, current 172.611679/3769: elapsed=17032.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.611679
last_received_ts = 172.611130
last_seq = 3769
current_ts = 172.628693
current_received_ts = 172.628159
current_seq = 3770
count = 25
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.611679/3769, current 172.628693/3770: elapsed=17021.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.628693
last_received_ts = 172.628159
last_seq = 3770
current_ts = 172.645737
current_received_ts = 172.645187
current_seq = 3771
count = 26
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.628693/3770, current 172.645737/3771: elapsed=17041.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.645737
last_received_ts = 172.645187
last_seq = 3771
current_ts = 172.662750
current_received_ts = 172.662216
current_seq = 3772
count = 27
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.645737/3771, current 172.662750/3772: elapsed=17019.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.662750
last_received_ts = 172.662216
last_seq = 3772
current_ts = 172.679779
current_received_ts = 172.679245
current_seq = 3773
count = 28
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.662750/3772, current 172.679779/3773: elapsed=17033.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.679779
last_received_ts = 172.679245
last_seq = 3773
current_ts = 172.696823
current_received_ts = 172.696304
current_seq = 3774
count = 29
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.679779/3773, current 172.696823/3774: elapsed=17033.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.696823
last_received_ts = 172.696304
last_seq = 3774
current_ts = 172.713852
current_received_ts = 172.713318
current_seq = 3775
count = 30
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.696823/3774, current 172.713852/3775: elapsed=17029.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.713852
last_received_ts = 172.713318
last_seq = 3775
current_ts = 172.730896
current_received_ts = 172.730347
current_seq = 3776
count = 31
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.713852/3775, current 172.730896/3776: elapsed=17044.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.730896
last_received_ts = 172.730347
last_seq = 3776
current_ts = 172.747925
current_received_ts = 172.747375
current_seq = 3777
count = 32
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.730896/3776, current 172.747925/3777: elapsed=17029.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.747925
last_received_ts = 172.747375
last_seq = 3777
current_ts = 172.764954
current_received_ts = 172.764404
current_seq = 3778
count = 33
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.747925/3777, current 172.764954/3778: elapsed=17031.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.764954
last_received_ts = 172.764404
last_seq = 3778
current_ts = 172.781967
current_received_ts = 172.781433
current_seq = 3779
count = 34
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.764954/3778, current 172.781967/3779: elapsed=17021.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.781967
last_received_ts = 172.781433
last_seq = 3779
current_ts = 172.799011
current_received_ts = 172.798462
current_seq = 3780
count = 35
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.781967/3779, current 172.799011/3780: elapsed=17031.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.799011
last_received_ts = 172.798462
last_seq = 3780
current_ts = 172.816040
current_received_ts = 172.815491
current_seq = 3781
count = 36
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.799011/3780, current 172.816040/3781: elapsed=17031.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.816040
last_received_ts = 172.815491
last_seq = 3781
current_ts = 172.833084
current_received_ts = 172.832520
current_seq = 3782
count = 37
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.816040/3781, current 172.833084/3782: elapsed=17044.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.833084
last_received_ts = 172.832520
last_seq = 3782
current_ts = 172.850098
current_received_ts = 172.849564
current_seq = 3783
count = 38
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.833084/3782, current 172.850098/3783: elapsed=17021.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.850098
last_received_ts = 172.849564
last_seq = 3783
current_ts = 172.867126
current_received_ts = 172.866592
current_seq = 3784
count = 39
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.850098/3783, current 172.867126/3784: elapsed=17031.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.867126
last_received_ts = 172.866592
last_seq = 3784
current_ts = 172.884171
current_received_ts = 172.883621
current_seq = 3785
count = 40
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.867126/3784, current 172.884171/3785: elapsed=17032.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.884171
last_received_ts = 172.883621
last_seq = 3785
current_ts = 172.901184
current_received_ts = 172.900650
current_seq = 3786
count = 41
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.884171/3785, current 172.901184/3786: elapsed=17028.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.901184
last_received_ts = 172.900650
last_seq = 3786
current_ts = 172.918228
current_received_ts = 172.917679
current_seq = 3787
count = 42
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.901184/3786, current 172.918228/3787: elapsed=17032.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.918228
last_received_ts = 172.917679
last_seq = 3787
current_ts = 172.935272
current_received_ts = 172.934708
current_seq = 3788
count = 43
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.918228/3787, current 172.935272/3788: elapsed=17045.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.935272
last_received_ts = 172.934708
last_seq = 3788
current_ts = 172.952301
current_received_ts = 172.951736
current_seq = 3789
count = 44
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.935272/3788, current 172.952301/3789: elapsed=17028.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.952301
last_received_ts = 172.951736
last_seq = 3789
current_ts = 172.969315
current_received_ts = 172.968781
current_seq = 3790
count = 45
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.952301/3789, current 172.969315/3790: elapsed=17022.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.969315
last_received_ts = 172.968781
last_seq = 3790
current_ts = 172.986343
current_received_ts = 172.985809
current_seq = 3791
count = 46
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.969315/3790, current 172.986343/3791: elapsed=17030.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 172.986343
last_received_ts = 172.985809
last_seq = 3791
current_ts = 173.003387
current_received_ts = 173.002838
current_seq = 3792
count = 47
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 172.986343/3791, current 173.003387/3792: elapsed=17034.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.003387
last_received_ts = 173.002838
last_seq = 3792
current_ts = 173.020416
current_received_ts = 173.019867
current_seq = 3793
count = 48
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.003387/3792, current 173.020416/3793: elapsed=17028.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.020416
last_received_ts = 173.019867
last_seq = 3793
current_ts = 173.037460
current_received_ts = 173.036896
current_seq = 3794
count = 49
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.020416/3793, current 173.037460/3794: elapsed=17046.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.037460
last_received_ts = 173.036896
last_seq = 3794
current_ts = 173.054489
current_received_ts = 173.053940
current_seq = 3795
count = 50
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.037460/3794, current 173.054489/3795: elapsed=17026.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.054489
last_received_ts = 173.053940
last_seq = 3795
current_ts = 173.071503
current_received_ts = 173.070969
current_seq = 3796
count = 51
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.054489/3795, current 173.071503/3796: elapsed=17023.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.071503
last_received_ts = 173.070969
last_seq = 3796
current_ts = 173.088547
current_received_ts = 173.087997
current_seq = 3797
count = 52
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.071503/3796, current 173.088547/3797: elapsed=17040.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.088547
last_received_ts = 173.087997
last_seq = 3797
current_ts = 173.105576
current_received_ts = 173.105072
current_seq = 3798
count = 53
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.088547/3797, current 173.105576/3798: elapsed=17034.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.105576
last_received_ts = 173.105072
last_seq = 3798
current_ts = 173.122604
current_received_ts = 173.122086
current_seq = 3799
count = 54
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.105576/3798, current 173.122604/3799: elapsed=17026.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.122604
last_received_ts = 173.122086
last_seq = 3799
current_ts = 173.139633
current_received_ts = 173.139114
current_seq = 3800
count = 55
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.122604/3799, current 173.139633/3800: elapsed=17025.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.139633
last_received_ts = 173.139114
last_seq = 3800
current_ts = 173.156677
current_received_ts = 173.156143
current_seq = 3801
count = 56
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.139633/3800, current 173.156677/3801: elapsed=17042.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.156677
last_received_ts = 173.156143
last_seq = 3801
current_ts = 173.173691
current_received_ts = 173.173157
current_seq = 3802
count = 57
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.156677/3801, current 173.173691/3802: elapsed=17023.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.173691
last_received_ts = 173.173157
last_seq = 3802
current_ts = 173.190735
current_received_ts = 173.190186
current_seq = 3803
count = 58
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.173691/3802, current 173.190735/3803: elapsed=17042.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.190735
last_received_ts = 173.190186
last_seq = 3803
current_ts = 173.207764
current_received_ts = 173.207214
current_seq = 3804
count = 59
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.190735/3803, current 173.207764/3804: elapsed=17020.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.207764
last_received_ts = 173.207214
last_seq = 3804
current_ts = 173.224792
current_received_ts = 173.224243
current_seq = 3805
count = 60
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.207764/3804, current 173.224792/3805: elapsed=17040.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.224792
last_received_ts = 173.224243
last_seq = 3805
current_ts = 173.241821
current_received_ts = 173.241272
current_seq = 3806
count = 61
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.224792/3805, current 173.241821/3806: elapsed=17029.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.241821
last_received_ts = 173.241272
last_seq = 3806
current_ts = 173.258850
current_received_ts = 173.258316
current_seq = 3807
count = 62
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.241821/3806, current 173.258850/3807: elapsed=17024.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.258850
last_received_ts = 173.258316
last_seq = 3807
current_ts = 173.275879
current_received_ts = 173.275345
current_seq = 3808
count = 63
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.258850/3807, current 173.275879/3808: elapsed=17030.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.275879
last_received_ts = 173.275345
last_seq = 3808
current_ts = 173.292908
current_received_ts = 173.292374
current_seq = 3809
count = 64
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.275879/3808, current 173.292908/3809: elapsed=17034.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.292908
last_received_ts = 173.292374
last_seq = 3809
current_ts = 173.309937
current_received_ts = 173.309402
current_seq = 3810
count = 65
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.292908/3809, current 173.309937/3810: elapsed=17029.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.309937
last_received_ts = 173.309402
last_seq = 3810
current_ts = 173.326981
current_received_ts = 173.326431
current_seq = 3811
count = 66
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.309937/3810, current 173.326981/3811: elapsed=17031.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.326981
last_received_ts = 173.326431
last_seq = 3811
current_ts = 173.344009
current_received_ts = 173.343460
current_seq = 3812
count = 67
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.326981/3811, current 173.344009/3812: elapsed=17042.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.344009
last_received_ts = 173.343460
last_seq = 3812
current_ts = 173.361053
current_received_ts = 173.360504
current_seq = 3813
count = 68
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.344009/3812, current 173.361053/3813: elapsed=17035.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.361053
last_received_ts = 173.360504
last_seq = 3813
current_ts = 173.378067
current_received_ts = 173.377533
current_seq = 3814
count = 69
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.361053/3813, current 173.378067/3814: elapsed=17016.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.378067
last_received_ts = 173.377533
last_seq = 3814
current_ts = 173.395111
current_received_ts = 173.394562
current_seq = 3815
count = 70
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.378067/3814, current 173.395111/3815: elapsed=17040.0us expected=17081.7us +- 85.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.395111
last_received_ts = 173.394562
last_seq = 3815
current_ts = 173.412125
current_received_ts = 173.411591
current_seq = 3816
count = 71
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.395111/3815, current 173.412125/3816: elapsed=17023.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.412125
last_received_ts = 173.411591
last_seq = 3816
current_ts = 173.429169
current_received_ts = 173.428619
current_seq = 3817
count = 72
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.412125/3816, current 173.429169/3817: elapsed=17033.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.429169
last_received_ts = 173.428619
last_seq = 3817
current_ts = 173.446198
current_received_ts = 173.445663
current_seq = 3818
count = 73
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.429169/3817, current 173.446198/3818: elapsed=17032.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.446198
last_received_ts = 173.445663
last_seq = 3818
current_ts = 173.463226
current_received_ts = 173.462677
current_seq = 3819
count = 74
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.446198/3818, current 173.463226/3819: elapsed=17038.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.463226
last_received_ts = 173.462677
last_seq = 3819
current_ts = 173.480270
current_received_ts = 173.479706
current_seq = 3820
count = 75
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.463226/3819, current 173.480270/3820: elapsed=17032.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.480270
last_received_ts = 173.479706
last_seq = 3820
current_ts = 173.497299
current_received_ts = 173.496765
current_seq = 3821
count = 76
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.480270/3820, current 173.497299/3821: elapsed=17030.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.497299
last_received_ts = 173.496765
last_seq = 3821
current_ts = 173.514328
current_received_ts = 173.513779
current_seq = 3822
count = 77
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.497299/3821, current 173.514328/3822: elapsed=17027.0us expected=17081.7us +- 85.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.514328
last_received_ts = 173.513779
last_seq = 3822
current_ts = 173.531326
current_received_ts = 173.530792
current_seq = 3823
count = 78
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.514328/3822, current 173.531326/3823: elapsed=17008.0us expected=17081.7us +- 85.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 173.531326
last_received_ts = 173.530792
last_seq = 3823
current_ts = 173.548325
current_received_ts = 173.547775
current_seq = 3824
count = 79
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 173.531326/3823, current 173.548325/3824: elapsed=16995.0us expected=17081.7us +- 85.4us, error 0.5%
(kms_flip:3849) DEBUG: inconsistent flip ts/seq: last 173.531326/3823, current 173.548325/3824: elapsed=16995.0us expected=17081.7us
(kms_flip:3849) DEBUG: expected 0, counted 79, encoder type 2
(kms_flip:3849) DEBUG: dropped frames, expected 0, counted 79, encoder type 2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3849) igt_core-INFO: Stack trace:
(kms_flip:3849) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3849) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3849) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3849) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3849) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3849) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3849) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3849) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (4.833s)
Starting dynamic subtest: C-HDMI-A2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3849) DEBUG: flip ts/seq: last 178.518784/107, current 178.535614/108: elapsed=16829.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.535614
last_received_ts = 178.535095
last_seq = 108
current_ts = 178.552444
current_received_ts = 178.551910
current_seq = 109
count = 87
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.535614/108, current 178.552444/109: elapsed=16839.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.552444
last_received_ts = 178.551910
last_seq = 109
current_ts = 178.569290
current_received_ts = 178.568741
current_seq = 110
count = 88
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.552444/109, current 178.569290/110: elapsed=16844.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.569290
last_received_ts = 178.568741
last_seq = 110
current_ts = 178.586136
current_received_ts = 178.585571
current_seq = 111
count = 89
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.569290/110, current 178.586136/111: elapsed=16833.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.586136
last_received_ts = 178.585571
last_seq = 111
current_ts = 178.602951
current_received_ts = 178.602417
current_seq = 112
count = 90
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.586136/111, current 178.602951/112: elapsed=16828.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.602951
last_received_ts = 178.602417
last_seq = 112
current_ts = 178.619797
current_received_ts = 178.619247
current_seq = 113
count = 91
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.602951/112, current 178.619797/113: elapsed=16833.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.619797
last_received_ts = 178.619247
last_seq = 113
current_ts = 178.636627
current_received_ts = 178.636093
current_seq = 114
count = 92
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.619797/113, current 178.636627/114: elapsed=16837.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.636627
last_received_ts = 178.636093
last_seq = 114
current_ts = 178.653473
current_received_ts = 178.652924
current_seq = 115
count = 93
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.636627/114, current 178.653473/115: elapsed=16844.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.653473
last_received_ts = 178.652924
last_seq = 115
current_ts = 178.670303
current_received_ts = 178.669754
current_seq = 116
count = 94
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.653473/115, current 178.670303/116: elapsed=16838.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.670303
last_received_ts = 178.669754
last_seq = 116
current_ts = 178.687134
current_received_ts = 178.686584
current_seq = 117
count = 95
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.670303/116, current 178.687134/117: elapsed=16831.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.687134
last_received_ts = 178.686584
last_seq = 117
current_ts = 178.703964
current_received_ts = 178.703430
current_seq = 118
count = 96
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.687134/117, current 178.703964/118: elapsed=16828.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.703964
last_received_ts = 178.703430
last_seq = 118
current_ts = 178.720810
current_received_ts = 178.720261
current_seq = 119
count = 97
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.703964/118, current 178.720810/119: elapsed=16844.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.720810
last_received_ts = 178.720261
last_seq = 119
current_ts = 178.737640
current_received_ts = 178.737106
current_seq = 120
count = 98
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.720810/119, current 178.737640/120: elapsed=16826.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.737640
last_received_ts = 178.737106
last_seq = 120
current_ts = 178.754486
current_received_ts = 178.753937
current_seq = 121
count = 99
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.737640/120, current 178.754486/121: elapsed=16848.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.754486
last_received_ts = 178.753937
last_seq = 121
current_ts = 178.771301
current_received_ts = 178.770767
current_seq = 122
count = 100
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.754486/121, current 178.771301/122: elapsed=16822.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.771301
last_received_ts = 178.770767
last_seq = 122
current_ts = 178.788147
current_received_ts = 178.787598
current_seq = 123
count = 101
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.771301/122, current 178.788147/123: elapsed=16845.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.788147
last_received_ts = 178.787598
last_seq = 123
current_ts = 178.804977
current_received_ts = 178.804443
current_seq = 124
count = 102
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.788147/123, current 178.804977/124: elapsed=16826.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.804977
last_received_ts = 178.804443
last_seq = 124
current_ts = 178.821823
current_received_ts = 178.821274
current_seq = 125
count = 103
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.804977/124, current 178.821823/125: elapsed=16837.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.821823
last_received_ts = 178.821274
last_seq = 125
current_ts = 178.838654
current_received_ts = 178.838120
current_seq = 126
count = 104
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.821823/125, current 178.838654/126: elapsed=16836.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.838654
last_received_ts = 178.838120
last_seq = 126
current_ts = 178.855484
current_received_ts = 178.854950
current_seq = 127
count = 105
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.838654/126, current 178.855484/127: elapsed=16833.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.855484
last_received_ts = 178.854950
last_seq = 127
current_ts = 178.872314
current_received_ts = 178.871780
current_seq = 128
count = 106
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.855484/127, current 178.872314/128: elapsed=16835.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.872314
last_received_ts = 178.871780
last_seq = 128
current_ts = 178.889160
current_received_ts = 178.888626
current_seq = 129
count = 107
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.872314/128, current 178.889160/129: elapsed=16838.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.889160
last_received_ts = 178.888626
last_seq = 129
current_ts = 178.906006
current_received_ts = 178.905441
current_seq = 130
count = 108
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.889160/129, current 178.906006/130: elapsed=16843.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.906006
last_received_ts = 178.905441
last_seq = 130
current_ts = 178.922821
current_received_ts = 178.922287
current_seq = 131
count = 109
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.906006/130, current 178.922821/131: elapsed=16827.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.922821
last_received_ts = 178.922287
last_seq = 131
current_ts = 178.939667
current_received_ts = 178.939117
current_seq = 132
count = 110
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.922821/131, current 178.939667/132: elapsed=16835.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.939667
last_received_ts = 178.939117
last_seq = 132
current_ts = 178.956512
current_received_ts = 178.955948
current_seq = 133
count = 111
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.939667/132, current 178.956512/133: elapsed=16845.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.956512
last_received_ts = 178.955948
last_seq = 133
current_ts = 178.973343
current_received_ts = 178.972794
current_seq = 134
count = 112
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.956512/133, current 178.973343/134: elapsed=16840.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.973343
last_received_ts = 178.972794
last_seq = 134
current_ts = 178.990173
current_received_ts = 178.989624
current_seq = 135
count = 113
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.973343/134, current 178.990173/135: elapsed=16830.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 178.990173
last_received_ts = 178.989624
last_seq = 135
current_ts = 179.007004
current_received_ts = 179.006470
current_seq = 136
count = 114
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 178.990173/135, current 179.007004/136: elapsed=16826.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.007004
last_received_ts = 179.006470
last_seq = 136
current_ts = 179.023849
current_received_ts = 179.023300
current_seq = 137
count = 115
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.007004/136, current 179.023849/137: elapsed=16850.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.023849
last_received_ts = 179.023300
last_seq = 137
current_ts = 179.040680
current_received_ts = 179.040131
current_seq = 138
count = 116
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.023849/137, current 179.040680/138: elapsed=16822.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.040680
last_received_ts = 179.040131
last_seq = 138
current_ts = 179.057510
current_received_ts = 179.056976
current_seq = 139
count = 117
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.040680/138, current 179.057510/139: elapsed=16835.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.057510
last_received_ts = 179.056976
last_seq = 139
current_ts = 179.074356
current_received_ts = 179.073807
current_seq = 140
count = 118
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.057510/139, current 179.074356/140: elapsed=16845.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.074356
last_received_ts = 179.073807
last_seq = 140
current_ts = 179.091202
current_received_ts = 179.090637
current_seq = 141
count = 119
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.074356/140, current 179.091202/141: elapsed=16839.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.091202
last_received_ts = 179.090637
last_seq = 141
current_ts = 179.108032
current_received_ts = 179.107483
current_seq = 142
count = 120
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.091202/141, current 179.108032/142: elapsed=16830.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.108032
last_received_ts = 179.107483
last_seq = 142
current_ts = 179.124863
current_received_ts = 179.124313
current_seq = 143
count = 121
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.108032/142, current 179.124863/143: elapsed=16842.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.124863
last_received_ts = 179.124313
last_seq = 143
current_ts = 179.141708
current_received_ts = 179.141144
current_seq = 144
count = 122
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.124863/143, current 179.141708/144: elapsed=16835.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.141708
last_received_ts = 179.141144
last_seq = 144
current_ts = 179.158539
current_received_ts = 179.157974
current_seq = 145
count = 123
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.141708/144, current 179.158539/145: elapsed=16831.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.158539
last_received_ts = 179.157974
last_seq = 145
current_ts = 179.175354
current_received_ts = 179.174820
current_seq = 146
count = 124
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.158539/145, current 179.175354/146: elapsed=16828.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.175354
last_received_ts = 179.174820
last_seq = 146
current_ts = 179.192200
current_received_ts = 179.191650
current_seq = 147
count = 125
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.175354/146, current 179.192200/147: elapsed=16844.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.192200
last_received_ts = 179.191650
last_seq = 147
current_ts = 179.209045
current_received_ts = 179.208496
current_seq = 148
count = 126
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.192200/147, current 179.209045/148: elapsed=16837.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.209045
last_received_ts = 179.208496
last_seq = 148
current_ts = 179.225876
current_received_ts = 179.225327
current_seq = 149
count = 127
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.209045/148, current 179.225876/149: elapsed=16838.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.225876
last_received_ts = 179.225327
last_seq = 149
current_ts = 179.242722
current_received_ts = 179.242157
current_seq = 150
count = 128
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.225876/149, current 179.242722/150: elapsed=16835.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.242722
last_received_ts = 179.242157
last_seq = 150
current_ts = 179.259537
current_received_ts = 179.259003
current_seq = 151
count = 129
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.242722/150, current 179.259537/151: elapsed=16822.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.259537
last_received_ts = 179.259003
last_seq = 151
current_ts = 179.276382
current_received_ts = 179.275833
current_seq = 152
count = 130
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.259537/151, current 179.276382/152: elapsed=16838.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.276382
last_received_ts = 179.275833
last_seq = 152
current_ts = 179.293213
current_received_ts = 179.292679
current_seq = 153
count = 131
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.276382/152, current 179.293213/153: elapsed=16836.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.293213
last_received_ts = 179.292679
last_seq = 153
current_ts = 179.310043
current_received_ts = 179.309509
current_seq = 154
count = 132
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.293213/153, current 179.310043/154: elapsed=16836.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.310043
last_received_ts = 179.309509
last_seq = 154
current_ts = 179.326889
current_received_ts = 179.326340
current_seq = 155
count = 133
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.310043/154, current 179.326889/155: elapsed=16845.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.326889
last_received_ts = 179.326340
last_seq = 155
current_ts = 179.343719
current_received_ts = 179.343170
current_seq = 156
count = 134
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.326889/155, current 179.343719/156: elapsed=16832.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.343719
last_received_ts = 179.343170
last_seq = 156
current_ts = 179.360550
current_received_ts = 179.360031
current_seq = 157
count = 135
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.343719/156, current 179.360550/157: elapsed=16827.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.360550
last_received_ts = 179.360031
last_seq = 157
current_ts = 179.377396
current_received_ts = 179.376862
current_seq = 158
count = 136
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.360550/157, current 179.377396/158: elapsed=16843.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.377396
last_received_ts = 179.376862
last_seq = 158
current_ts = 179.394226
current_received_ts = 179.393677
current_seq = 159
count = 137
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.377396/158, current 179.394226/159: elapsed=16837.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.394226
last_received_ts = 179.393677
last_seq = 159
current_ts = 179.411057
current_received_ts = 179.410522
current_seq = 160
count = 138
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.394226/159, current 179.411057/160: elapsed=16832.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.411057
last_received_ts = 179.410522
last_seq = 160
current_ts = 179.427902
current_received_ts = 179.427353
current_seq = 161
count = 139
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.411057/160, current 179.427902/161: elapsed=16843.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.427902
last_received_ts = 179.427353
last_seq = 161
current_ts = 179.444733
current_received_ts = 179.444199
current_seq = 162
count = 140
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.427902/161, current 179.444733/162: elapsed=16829.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.444733
last_received_ts = 179.444199
last_seq = 162
current_ts = 179.461578
current_received_ts = 179.461044
current_seq = 163
count = 141
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.444733/162, current 179.461578/163: elapsed=16840.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.461578
last_received_ts = 179.461044
last_seq = 163
current_ts = 179.478409
current_received_ts = 179.477859
current_seq = 164
count = 142
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.461578/163, current 179.478409/164: elapsed=16837.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.478409
last_received_ts = 179.477859
last_seq = 164
current_ts = 179.495239
current_received_ts = 179.494690
current_seq = 165
count = 143
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.478409/164, current 179.495239/165: elapsed=16823.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.495239
last_received_ts = 179.494690
last_seq = 165
current_ts = 179.512085
current_received_ts = 179.511520
current_seq = 166
count = 144
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.495239/165, current 179.512085/166: elapsed=16843.0us expected=16883.8us +- 84.4us, error 0.2%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.512085
last_received_ts = 179.511520
last_seq = 166
current_ts = 179.528915
current_received_ts = 179.528351
current_seq = 167
count = 145
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.512085/166, current 179.528915/167: elapsed=16831.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.528915
last_received_ts = 179.528351
last_seq = 167
current_ts = 179.545715
current_received_ts = 179.545181
current_seq = 168
count = 146
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.528915/167, current 179.545715/168: elapsed=16806.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.545715
last_received_ts = 179.545181
last_seq = 168
current_ts = 179.562546
current_received_ts = 179.561981
current_seq = 169
count = 147
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.545715/168, current 179.562546/169: elapsed=16826.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.562546
last_received_ts = 179.561981
last_seq = 169
current_ts = 179.579346
current_received_ts = 179.578812
current_seq = 170
count = 148
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.562546/169, current 179.579346/170: elapsed=16804.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.579346
last_received_ts = 179.578812
last_seq = 170
current_ts = 179.596176
current_received_ts = 179.595627
current_seq = 171
count = 149
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.579346/170, current 179.596176/171: elapsed=16827.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.596176
last_received_ts = 179.595627
last_seq = 171
current_ts = 179.612991
current_received_ts = 179.612442
current_seq = 172
count = 150
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.596176/171, current 179.612991/172: elapsed=16813.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.612991
last_received_ts = 179.612442
last_seq = 172
current_ts = 179.629807
current_received_ts = 179.629242
current_seq = 173
count = 151
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.612991/172, current 179.629807/173: elapsed=16816.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.629807
last_received_ts = 179.629242
last_seq = 173
current_ts = 179.646606
current_received_ts = 179.646072
current_seq = 174
count = 152
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.629807/173, current 179.646606/174: elapsed=16808.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.646606
last_received_ts = 179.646072
last_seq = 174
current_ts = 179.663422
current_received_ts = 179.662888
current_seq = 175
count = 153
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.646606/174, current 179.663422/175: elapsed=16816.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.663422
last_received_ts = 179.662888
last_seq = 175
current_ts = 179.680252
current_received_ts = 179.679688
current_seq = 176
count = 154
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.663422/175, current 179.680252/176: elapsed=16823.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.680252
last_received_ts = 179.679688
last_seq = 176
current_ts = 179.697067
current_received_ts = 179.696518
current_seq = 177
count = 155
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.680252/176, current 179.697067/177: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.697067
last_received_ts = 179.696518
last_seq = 177
current_ts = 179.713867
current_received_ts = 179.713333
current_seq = 178
count = 156
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.697067/177, current 179.713867/178: elapsed=16807.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.713867
last_received_ts = 179.713333
last_seq = 178
current_ts = 179.730682
current_received_ts = 179.730148
current_seq = 179
count = 157
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.713867/178, current 179.730682/179: elapsed=16816.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.730682
last_received_ts = 179.730148
last_seq = 179
current_ts = 179.747513
current_received_ts = 179.746964
current_seq = 180
count = 158
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.730682/179, current 179.747513/180: elapsed=16825.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.747513
last_received_ts = 179.746964
last_seq = 180
current_ts = 179.764313
current_received_ts = 179.763779
current_seq = 181
count = 159
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.747513/180, current 179.764313/181: elapsed=16806.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.764313
last_received_ts = 179.763779
last_seq = 181
current_ts = 179.781128
current_received_ts = 179.780594
current_seq = 182
count = 160
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.764313/181, current 179.781128/182: elapsed=16815.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.781128
last_received_ts = 179.780594
last_seq = 182
current_ts = 179.797943
current_received_ts = 179.797409
current_seq = 183
count = 161
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.781128/182, current 179.797943/183: elapsed=16817.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.797943
last_received_ts = 179.797409
last_seq = 183
current_ts = 179.814758
current_received_ts = 179.814224
current_seq = 184
count = 162
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.797943/183, current 179.814758/184: elapsed=16815.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.814758
last_received_ts = 179.814224
last_seq = 184
current_ts = 179.831589
current_received_ts = 179.831055
current_seq = 185
count = 163
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.814758/184, current 179.831589/185: elapsed=16825.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.831589
last_received_ts = 179.831055
last_seq = 185
current_ts = 179.848389
current_received_ts = 179.847885
current_seq = 186
count = 164
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.831589/185, current 179.848389/186: elapsed=16808.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.848389
last_received_ts = 179.847885
last_seq = 186
current_ts = 179.865204
current_received_ts = 179.864670
current_seq = 187
count = 165
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.848389/186, current 179.865204/187: elapsed=16813.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.865204
last_received_ts = 179.864670
last_seq = 187
current_ts = 179.882019
current_received_ts = 179.881485
current_seq = 188
count = 166
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.865204/187, current 179.882019/188: elapsed=16817.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.882019
last_received_ts = 179.881485
last_seq = 188
current_ts = 179.898849
current_received_ts = 179.898300
current_seq = 189
count = 167
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.882019/188, current 179.898849/189: elapsed=16825.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.898849
last_received_ts = 179.898300
last_seq = 189
current_ts = 179.915665
current_received_ts = 179.915115
current_seq = 190
count = 168
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.898849/189, current 179.915665/190: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.915665
last_received_ts = 179.915115
last_seq = 190
current_ts = 179.932480
current_received_ts = 179.931946
current_seq = 191
count = 169
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.915665/190, current 179.932480/191: elapsed=16819.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.932480
last_received_ts = 179.931946
last_seq = 191
current_ts = 179.949295
current_received_ts = 179.948746
current_seq = 192
count = 170
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.932480/191, current 179.949295/192: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.949295
last_received_ts = 179.948746
last_seq = 192
current_ts = 179.966110
current_received_ts = 179.965561
current_seq = 193
count = 171
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.949295/192, current 179.966110/193: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.966110
last_received_ts = 179.965561
last_seq = 193
current_ts = 179.982925
current_received_ts = 179.982376
current_seq = 194
count = 172
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.966110/193, current 179.982925/194: elapsed=16820.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.982925
last_received_ts = 179.982376
last_seq = 194
current_ts = 179.999741
current_received_ts = 179.999191
current_seq = 195
count = 173
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.982925/194, current 179.999741/195: elapsed=16815.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 179.999741
last_received_ts = 179.999191
last_seq = 195
current_ts = 180.016556
current_received_ts = 180.016052
current_seq = 196
count = 174
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 179.999741/195, current 180.016556/196: elapsed=16802.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.016556
last_received_ts = 180.016052
last_seq = 196
current_ts = 180.033371
current_received_ts = 180.032837
current_seq = 197
count = 175
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.016556/196, current 180.033371/197: elapsed=16820.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.033371
last_received_ts = 180.032837
last_seq = 197
current_ts = 180.050186
current_received_ts = 180.049652
current_seq = 198
count = 176
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.033371/197, current 180.050186/198: elapsed=16816.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.050186
last_received_ts = 180.049652
last_seq = 198
current_ts = 180.067001
current_received_ts = 180.066467
current_seq = 199
count = 177
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.050186/198, current 180.067001/199: elapsed=16821.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.067001
last_received_ts = 180.066467
last_seq = 199
current_ts = 180.083817
current_received_ts = 180.083298
current_seq = 200
count = 178
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.067001/199, current 180.083817/200: elapsed=16812.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.083817
last_received_ts = 180.083298
last_seq = 200
current_ts = 180.100647
current_received_ts = 180.100082
current_seq = 201
count = 179
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.083817/200, current 180.100647/201: elapsed=16823.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.100647
last_received_ts = 180.100082
last_seq = 201
current_ts = 180.117447
current_received_ts = 180.116898
current_seq = 202
count = 180
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.100647/201, current 180.117447/202: elapsed=16810.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.117447
last_received_ts = 180.116898
last_seq = 202
current_ts = 180.134262
current_received_ts = 180.133728
current_seq = 203
count = 181
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.117447/202, current 180.134262/203: elapsed=16808.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.134262
last_received_ts = 180.133728
last_seq = 203
current_ts = 180.151077
current_received_ts = 180.150543
current_seq = 204
count = 182
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.134262/203, current 180.151077/204: elapsed=16818.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.151077
last_received_ts = 180.150543
last_seq = 204
current_ts = 180.167892
current_received_ts = 180.167343
current_seq = 205
count = 183
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.151077/204, current 180.167892/205: elapsed=16812.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.167892
last_received_ts = 180.167343
last_seq = 205
current_ts = 180.184708
current_received_ts = 180.184158
current_seq = 206
count = 184
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.167892/205, current 180.184708/206: elapsed=16815.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.184708
last_received_ts = 180.184158
last_seq = 206
current_ts = 180.201523
current_received_ts = 180.200989
current_seq = 207
count = 185
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.184708/206, current 180.201523/207: elapsed=16818.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.201523
last_received_ts = 180.200989
last_seq = 207
current_ts = 180.218338
current_received_ts = 180.217789
current_seq = 208
count = 186
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.201523/207, current 180.218338/208: elapsed=16823.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.218338
last_received_ts = 180.217789
last_seq = 208
current_ts = 180.235153
current_received_ts = 180.234604
current_seq = 209
count = 187
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.218338/208, current 180.235153/209: elapsed=16815.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.235153
last_received_ts = 180.234604
last_seq = 209
current_ts = 180.251984
current_received_ts = 180.251419
current_seq = 210
count = 188
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.235153/209, current 180.251984/210: elapsed=16817.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.251984
last_received_ts = 180.251419
last_seq = 210
current_ts = 180.268784
current_received_ts = 180.268250
current_seq = 211
count = 189
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.251984/210, current 180.268784/211: elapsed=16805.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.268784
last_received_ts = 180.268250
last_seq = 211
current_ts = 180.285599
current_received_ts = 180.285065
current_seq = 212
count = 190
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.268784/211, current 180.285599/212: elapsed=16821.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.285599
last_received_ts = 180.285065
last_seq = 212
current_ts = 180.302414
current_received_ts = 180.301880
current_seq = 213
count = 191
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.285599/212, current 180.302414/213: elapsed=16811.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.302414
last_received_ts = 180.301880
last_seq = 213
current_ts = 180.319244
current_received_ts = 180.318680
current_seq = 214
count = 192
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.302414/213, current 180.319244/214: elapsed=16825.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.319244
last_received_ts = 180.318680
last_seq = 214
current_ts = 180.336060
current_received_ts = 180.335510
current_seq = 215
count = 193
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.319244/214, current 180.336060/215: elapsed=16820.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.336060
last_received_ts = 180.335510
last_seq = 215
current_ts = 180.352875
current_received_ts = 180.352310
current_seq = 216
count = 194
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.336060/215, current 180.352875/216: elapsed=16811.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.352875
last_received_ts = 180.352310
last_seq = 216
current_ts = 180.369675
current_received_ts = 180.369141
current_seq = 217
count = 195
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.352875/216, current 180.369675/217: elapsed=16806.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.369675
last_received_ts = 180.369141
last_seq = 217
current_ts = 180.386505
current_received_ts = 180.385956
current_seq = 218
count = 196
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.369675/217, current 180.386505/218: elapsed=16823.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.386505
last_received_ts = 180.385956
last_seq = 218
current_ts = 180.403305
current_received_ts = 180.402771
current_seq = 219
count = 197
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.386505/218, current 180.403305/219: elapsed=16809.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.403305
last_received_ts = 180.402771
last_seq = 219
current_ts = 180.420120
current_received_ts = 180.419586
current_seq = 220
count = 198
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.403305/219, current 180.420120/220: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.420120
last_received_ts = 180.419586
last_seq = 220
current_ts = 180.436951
current_received_ts = 180.436401
current_seq = 221
count = 199
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.420120/220, current 180.436951/221: elapsed=16830.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.436951
last_received_ts = 180.436401
last_seq = 221
current_ts = 180.453766
current_received_ts = 180.453217
current_seq = 222
count = 200
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.436951/221, current 180.453766/222: elapsed=16808.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.453766
last_received_ts = 180.453217
last_seq = 222
current_ts = 180.470566
current_received_ts = 180.470047
current_seq = 223
count = 201
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.453766/222, current 180.470566/223: elapsed=16810.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.470566
last_received_ts = 180.470047
last_seq = 223
current_ts = 180.487396
current_received_ts = 180.486847
current_seq = 224
count = 202
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.470566/223, current 180.487396/224: elapsed=16829.0us expected=16883.8us +- 84.4us, error 0.3%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.487396
last_received_ts = 180.486847
last_seq = 224
current_ts = 180.504211
current_received_ts = 180.503662
current_seq = 225
count = 203
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.487396/224, current 180.504211/225: elapsed=16806.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.504211
last_received_ts = 180.503662
last_seq = 225
current_ts = 180.521027
current_received_ts = 180.520477
current_seq = 226
count = 204
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.504211/225, current 180.521027/226: elapsed=16814.0us expected=16883.8us +- 84.4us, error 0.4%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.521027
last_received_ts = 180.520477
last_seq = 226
current_ts = 180.537827
current_received_ts = 180.537292
current_seq = 227
count = 205
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.521027/226, current 180.537827/227: elapsed=16806.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: name = flip
last_ts = 180.537827
last_received_ts = 180.537292
last_seq = 227
current_ts = 180.554626
current_received_ts = 180.554092
current_seq = 228
count = 206
seq_step = 1
(kms_flip:3849) DEBUG: flip ts/seq: last 180.537827/227, current 180.554626/228: elapsed=16799.0us expected=16883.8us +- 84.4us, error 0.5%
(kms_flip:3849) DEBUG: inconsistent flip ts/seq: last 180.537827/227, current 180.554626/228: elapsed=16799.0us expected=16883.8us
(kms_flip:3849) DEBUG: expected 0, counted 206, encoder type 2
(kms_flip:3849) DEBUG: dropped frames, expected 0, counted 206, encoder type 2
(kms_flip:3849) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3849) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3849) igt_core-INFO: Stack trace:
(kms_flip:3849) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3849) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3849) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3849) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3849) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3849) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3849) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3849) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A2: FAIL (7.246s)
Starting dynamic subtest: D-HDMI-A2
Dynamic subtest D-HDMI-A2: SUCCESS (4.254s)
Starting dynamic subtest: A-DP2
Dynamic subtest A-DP2: SUCCESS (4.291s)
Starting dynamic subtest: B-DP2
Dynamic subtest B-DP2: SUCCESS (4.280s)
Starting dynamic subtest: C-DP2
Dynamic subtest C-DP2: SUCCESS (4.255s)
Starting dynamic subtest: D-DP2
Dynamic subtest D-DP2: SUCCESS (4.249s)
Subtest plain-flip-ts-check: FAIL (37.349s)