Results for igt@kms_flip@2x-plain-flip-fb-recreate

shard-dg2-463

IGT-Version: 1.30-g48a70f679 (x86_64) (Linux: 6.13.0-rc2-xe+ x86_64)

Using IGT_SRANDOM=1734337271 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: 2x-plain-flip-fb-recreate
Starting dynamic subtest: AB-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16038.6us +- 166.786us accuracy 3.12%
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __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 AB-HDMI-A6-DP4: FAIL (0.656s)
Starting dynamic subtest: AC-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 15993.0us +- 5.164us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 15993us +- 5.164us, difference 673.7us (130.5 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:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __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 AC-HDMI-A6-DP4: FAIL (3.906s)
Starting dynamic subtest: AD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16268.0us +- 6.512us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16268us +- 6.512us, difference 398.7us (61.2 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:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __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 AD-HDMI-A6-DP4: FAIL (5.080s)
Starting dynamic subtest: BC-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16458.2us +- 6.421us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16458us +- 6.421us, difference 208.5us (32.5 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:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __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 BC-HDMI-A6-DP4: FAIL (7.473s)
Starting dynamic subtest: BD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16582.2us +- 6.414us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16582us +- 6.414us, difference 84.4us (13.2 sigma)
Dynamic subtest BD-HDMI-A6-DP4: SUCCESS (5.681s)
Starting dynamic subtest: CD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16623.5us +- 3.502us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16624us +- 3.502us, difference 43.2us (12.3 sigma)
Dynamic subtest CD-HDMI-A6-DP4: SUCCESS (5.657s)
Subtest 2x-plain-flip-fb-recreate: FAIL (28.498s)

Starting subtest: 2x-plain-flip-fb-recreate
Starting dynamic subtest: AB-HDMI-A6-DP4
(kms_flip:8259) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:8259) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
Dynamic subtest AB-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89aebe30, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89aebe30, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89af5190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:8259) DEBUG: No stale events found
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) INFO: Expected frametime: 16667us; measured 16038.6us +- 166.786us accuracy 3.12%
(kms_flip:8259) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:8259) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
(kms_flip:8259) igt_core-INFO: Stack trace:
(kms_flip:8259) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:8259) igt_core-INFO:   #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
(kms_flip:8259) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:8259) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:8259) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:8259) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:8259) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:8259) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-HDMI-A6-DP4: FAIL (0.656s)
Starting dynamic subtest: AC-HDMI-A6-DP4
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4bc30, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4bc30, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a790, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a790, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5a910, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:8259) DEBUG: No stale events found
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) INFO: Expected frametime: 16667us; measured 15993.0us +- 5.164us accuracy 0.10%
(kms_flip:8259) INFO: vblank interval differs from modeline! expected 16666.7us, measured 15993us +- 5.164us, difference 673.7us (130.5 sigma)
(kms_flip:8259) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 341.214996
current_received_ts = 341.214508
current_seq = 6752
count = 0
seq_step = 1
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.214996
last_received_ts = 341.214508
last_seq = 6752
current_ts = 341.230988
current_received_ts = 341.230499
current_seq = 6753
count = 1
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.214996/6752, current 341.230988/6753: elapsed=15986.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.230988
last_received_ts = 341.230499
last_seq = 6753
current_ts = 341.246979
current_received_ts = 341.246490
current_seq = 6754
count = 2
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.230988/6753, current 341.246979/6754: elapsed=15998.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.246979
last_received_ts = 341.246490
last_seq = 6754
current_ts = 341.262970
current_received_ts = 341.262482
current_seq = 6755
count = 3
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.246979/6754, current 341.262970/6755: elapsed=15996.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.262970
last_received_ts = 341.262482
last_seq = 6755
current_ts = 341.278961
current_received_ts = 341.278473
current_seq = 6756
count = 4
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.262970/6755, current 341.278961/6756: elapsed=15990.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.278961
last_received_ts = 341.278473
last_seq = 6756
current_ts = 341.294952
current_received_ts = 341.294464
current_seq = 6757
count = 5
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.278961/6756, current 341.294952/6757: elapsed=15992.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.294952
last_received_ts = 341.294464
last_seq = 6757
current_ts = 341.310944
current_received_ts = 341.310455
current_seq = 6758
count = 6
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.294952/6757, current 341.310944/6758: elapsed=15993.0us expected=15993.0us +- 80.0us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.310944
last_received_ts = 341.310455
last_seq = 6758
current_ts = 341.326965
current_received_ts = 341.326477
current_seq = 6759
count = 7
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.310944/6758, current 341.326965/6759: elapsed=16015.0us expected=15993.0us +- 80.0us, error 0.1%
(kms_flip:8259) DEBUG: name = flip
last_ts = 341.326965
last_received_ts = 341.326477
last_seq = 6759
current_ts = 341.343048
current_received_ts = 341.342529
current_seq = 6760
count = 8
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 341.326965/6759, current 341.343048/6760: elapsed=16076.0us expected=15993.0us +- 80.0us, error 0.5%
(kms_flip:8259) DEBUG: inconsistent flip ts/seq: last 341.326965/6759, current 341.343048/6760: elapsed=16076.0us expected=15993.0us
(kms_flip:8259) DEBUG: expected 13375, counted 8, encoder type 2
(kms_flip:8259) DEBUG: dropped frames, expected 13375, counted 8, encoder type 2
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:8259) igt_core-INFO: Stack trace:
(kms_flip:8259) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:8259) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:8259) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:8259) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:8259) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:8259) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:8259) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:8259) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-HDMI-A6-DP4: FAIL (3.906s)
Starting dynamic subtest: AD-HDMI-A6-DP4
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AD-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=5, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:8259) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=6, pitch=7680)
(kms_flip:8259) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b519f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b519f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4f810, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4f810, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4f810, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b4f810, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5bac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) intel_allocator_simple-DEBUG: <ial: 0x62bb89b5bac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:8259) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:8259) DEBUG: No stale events found
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:8259) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:8259) INFO: Expected frametime: 16667us; measured 16268.0us +- 6.512us accuracy 0.12%
(kms_flip:8259) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16268us +- 6.512us, difference 398.7us (61.2 sigma)
(kms_flip:8259) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 345.004944
current_received_ts = 345.004425
current_seq = 6970
count = 0
seq_step = 1
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.004944
last_received_ts = 345.004425
last_seq = 6970
current_ts = 345.021210
current_received_ts = 345.020721
current_seq = 6971
count = 1
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.004944/6970, current 345.021210/6971: elapsed=16270.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.021210
last_received_ts = 345.020721
last_seq = 6971
current_ts = 345.037476
current_received_ts = 345.036987
current_seq = 6972
count = 2
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.021210/6971, current 345.037476/6972: elapsed=16266.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.037476
last_received_ts = 345.036987
last_seq = 6972
current_ts = 345.053741
current_received_ts = 345.053192
current_seq = 6973
count = 3
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.037476/6972, current 345.053741/6973: elapsed=16275.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.053741
last_received_ts = 345.053192
last_seq = 6973
current_ts = 345.070007
current_received_ts = 345.069519
current_seq = 6974
count = 4
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.053741/6973, current 345.070007/6974: elapsed=16263.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.070007
last_received_ts = 345.069519
last_seq = 6974
current_ts = 345.086273
current_received_ts = 345.085785
current_seq = 6975
count = 5
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.070007/6974, current 345.086273/6975: elapsed=16268.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.086273
last_received_ts = 345.085785
last_seq = 6975
current_ts = 345.102539
current_received_ts = 345.102081
current_seq = 6976
count = 6
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.086273/6975, current 345.102539/6976: elapsed=16270.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.102539
last_received_ts = 345.102081
last_seq = 6976
current_ts = 345.118805
current_received_ts = 345.118317
current_seq = 6977
count = 7
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.102539/6976, current 345.118805/6977: elapsed=16271.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.118805
last_received_ts = 345.118317
last_seq = 6977
current_ts = 345.135071
current_received_ts = 345.134583
current_seq = 6978
count = 8
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.118805/6977, current 345.135071/6978: elapsed=16264.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.135071
last_received_ts = 345.134583
last_seq = 6978
current_ts = 345.151367
current_received_ts = 345.150848
current_seq = 6979
count = 9
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.135071/6978, current 345.151367/6979: elapsed=16270.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.151367
last_received_ts = 345.150848
last_seq = 6979
current_ts = 345.167633
current_received_ts = 345.167145
current_seq = 6980
count = 10
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.151367/6979, current 345.167633/6980: elapsed=16268.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.167633
last_received_ts = 345.167145
last_seq = 6980
current_ts = 345.183899
current_received_ts = 345.183380
current_seq = 6981
count = 11
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.167633/6980, current 345.183899/6981: elapsed=16270.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.183899
last_received_ts = 345.183380
last_seq = 6981
current_ts = 345.200165
current_received_ts = 345.199646
current_seq = 6982
count = 12
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.183899/6981, current 345.200165/6982: elapsed=16266.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.200165
last_received_ts = 345.199646
last_seq = 6982
current_ts = 345.216431
current_received_ts = 345.215942
current_seq = 6983
count = 13
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.200165/6982, current 345.216431/6983: elapsed=16271.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.216431
last_received_ts = 345.215942
last_seq = 6983
current_ts = 345.232697
current_received_ts = 345.232208
current_seq = 6984
count = 14
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.216431/6983, current 345.232697/6984: elapsed=16262.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.232697
last_received_ts = 345.232208
last_seq = 6984
current_ts = 345.248962
current_received_ts = 345.248444
current_seq = 6985
count = 15
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.232697/6984, current 345.248962/6985: elapsed=16278.0us expected=16268.0us +- 81.3us, error 0.1%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.248962
last_received_ts = 345.248444
last_seq = 6985
current_ts = 345.265228
current_received_ts = 345.264740
current_seq = 6986
count = 16
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.248962/6985, current 345.265228/6986: elapsed=16263.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.265228
last_received_ts = 345.264740
last_seq = 6986
current_ts = 345.281494
current_received_ts = 345.281036
current_seq = 6987
count = 17
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.265228/6986, current 345.281494/6987: elapsed=16269.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.281494
last_received_ts = 345.281036
last_seq = 6987
current_ts = 345.297760
current_received_ts = 345.297302
current_seq = 6988
count = 18
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.281494/6987, current 345.297760/6988: elapsed=16269.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.297760
last_received_ts = 345.297302
last_seq = 6988
current_ts = 345.314026
current_received_ts = 345.313538
current_seq = 6989
count = 19
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.297760/6988, current 345.314026/6989: elapsed=16268.0us expected=16268.0us +- 81.3us, error 0.0%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.314026
last_received_ts = 345.313538
last_seq = 6989
current_ts = 345.330322
current_received_ts = 345.329895
current_seq = 6990
count = 20
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.314026/6989, current 345.330322/6990: elapsed=16291.0us expected=16268.0us +- 81.3us, error 0.1%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.330322
last_received_ts = 345.329895
last_seq = 6990
current_ts = 345.346649
current_received_ts = 345.346252
current_seq = 6991
count = 21
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.330322/6990, current 345.346649/6991: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.346649
last_received_ts = 345.346252
last_seq = 6991
current_ts = 345.362976
current_received_ts = 345.362518
current_seq = 6992
count = 22
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.346649/6991, current 345.362976/6992: elapsed=16322.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.362976
last_received_ts = 345.362518
last_seq = 6992
current_ts = 345.379272
current_received_ts = 345.378845
current_seq = 6993
count = 23
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.362976/6992, current 345.379272/6993: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.379272
last_received_ts = 345.378845
last_seq = 6993
current_ts = 345.395599
current_received_ts = 345.395172
current_seq = 6994
count = 24
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.379272/6993, current 345.395599/6994: elapsed=16314.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.395599
last_received_ts = 345.395172
last_seq = 6994
current_ts = 345.411926
current_received_ts = 345.411469
current_seq = 6995
count = 25
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.395599/6994, current 345.411926/6995: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.411926
last_received_ts = 345.411469
last_seq = 6995
current_ts = 345.428223
current_received_ts = 345.427734
current_seq = 6996
count = 26
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.411926/6995, current 345.428223/6996: elapsed=16314.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.428223
last_received_ts = 345.427734
last_seq = 6996
current_ts = 345.444550
current_received_ts = 345.444183
current_seq = 6997
count = 27
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.428223/6996, current 345.444550/6997: elapsed=16321.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.444550
last_received_ts = 345.444183
last_seq = 6997
current_ts = 345.460876
current_received_ts = 345.460419
current_seq = 6998
count = 28
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.444550/6997, current 345.460876/6998: elapsed=16321.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.460876
last_received_ts = 345.460419
last_seq = 6998
current_ts = 345.477173
current_received_ts = 345.476715
current_seq = 6999
count = 29
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.460876/6998, current 345.477173/6999: elapsed=16313.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.477173
last_received_ts = 345.476715
last_seq = 6999
current_ts = 345.493500
current_received_ts = 345.493042
current_seq = 7000
count = 30
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.477173/6999, current 345.493500/7000: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.493500
last_received_ts = 345.493042
last_seq = 7000
current_ts = 345.509827
current_received_ts = 345.509369
current_seq = 7001
count = 31
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.493500/7000, current 345.509827/7001: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.509827
last_received_ts = 345.509369
last_seq = 7001
current_ts = 345.526123
current_received_ts = 345.525696
current_seq = 7002
count = 32
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.509827/7001, current 345.526123/7002: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.526123
last_received_ts = 345.525696
last_seq = 7002
current_ts = 345.542450
current_received_ts = 345.542053
current_seq = 7003
count = 33
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.526123/7002, current 345.542450/7003: elapsed=16320.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.542450
last_received_ts = 345.542053
last_seq = 7003
current_ts = 345.558777
current_received_ts = 345.558289
current_seq = 7004
count = 34
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.542450/7003, current 345.558777/7004: elapsed=16313.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.558777
last_received_ts = 345.558289
last_seq = 7004
current_ts = 345.575104
current_received_ts = 345.574646
current_seq = 7005
count = 35
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.558777/7004, current 345.575104/7005: elapsed=16320.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.575104
last_received_ts = 345.574646
last_seq = 7005
current_ts = 345.591400
current_received_ts = 345.590973
current_seq = 7006
count = 36
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.575104/7005, current 345.591400/7006: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.591400
last_received_ts = 345.590973
last_seq = 7006
current_ts = 345.607727
current_received_ts = 345.607269
current_seq = 7007
count = 37
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.591400/7006, current 345.607727/7007: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.607727
last_received_ts = 345.607269
last_seq = 7007
current_ts = 345.624054
current_received_ts = 345.623627
current_seq = 7008
count = 38
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.607727/7007, current 345.624054/7008: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.624054
last_received_ts = 345.623627
last_seq = 7008
current_ts = 345.640350
current_received_ts = 345.639923
current_seq = 7009
count = 39
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.624054/7008, current 345.640350/7009: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.640350
last_received_ts = 345.639923
last_seq = 7009
current_ts = 345.656677
current_received_ts = 345.656250
current_seq = 7010
count = 40
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.640350/7009, current 345.656677/7010: elapsed=16311.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.656677
last_received_ts = 345.656250
last_seq = 7010
current_ts = 345.672974
current_received_ts = 345.672485
current_seq = 7011
count = 41
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.656677/7010, current 345.672974/7011: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.672974
last_received_ts = 345.672485
last_seq = 7011
current_ts = 345.689301
current_received_ts = 345.688751
current_seq = 7012
count = 42
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.672974/7011, current 345.689301/7012: elapsed=16320.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.689301
last_received_ts = 345.688751
last_seq = 7012
current_ts = 345.705627
current_received_ts = 345.705139
current_seq = 7013
count = 43
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.689301/7012, current 345.705627/7013: elapsed=16314.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.705627
last_received_ts = 345.705139
last_seq = 7013
current_ts = 345.721924
current_received_ts = 345.721375
current_seq = 7014
count = 44
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.705627/7013, current 345.721924/7014: elapsed=16315.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.721924
last_received_ts = 345.721375
last_seq = 7014
current_ts = 345.738281
current_received_ts = 345.737701
current_seq = 7015
count = 45
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.721924/7014, current 345.738281/7015: elapsed=16330.0us expected=16268.0us +- 81.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.738281
last_received_ts = 345.737701
last_seq = 7015
current_ts = 345.754578
current_received_ts = 345.754150
current_seq = 7016
count = 46
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.738281/7015, current 345.754578/7016: elapsed=16310.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.754578
last_received_ts = 345.754150
last_seq = 7016
current_ts = 345.770874
current_received_ts = 345.770416
current_seq = 7017
count = 47
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.754578/7016, current 345.770874/7017: elapsed=16311.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.770874
last_received_ts = 345.770416
last_seq = 7017
current_ts = 345.787201
current_received_ts = 345.786774
current_seq = 7018
count = 48
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.770874/7017, current 345.787201/7018: elapsed=16328.0us expected=16268.0us +- 81.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.787201
last_received_ts = 345.786774
last_seq = 7018
current_ts = 345.803528
current_received_ts = 345.803131
current_seq = 7019
count = 49
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.787201/7018, current 345.803528/7019: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.803528
last_received_ts = 345.803131
last_seq = 7019
current_ts = 345.819855
current_received_ts = 345.819397
current_seq = 7020
count = 50
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.803528/7019, current 345.819855/7020: elapsed=16319.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.819855
last_received_ts = 345.819397
last_seq = 7020
current_ts = 345.836182
current_received_ts = 345.835724
current_seq = 7021
count = 51
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.819855/7020, current 345.836182/7021: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.836182
last_received_ts = 345.835724
last_seq = 7021
current_ts = 345.852478
current_received_ts = 345.851990
current_seq = 7022
count = 52
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.836182/7021, current 345.852478/7022: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.852478
last_received_ts = 345.851990
last_seq = 7022
current_ts = 345.868805
current_received_ts = 345.868317
current_seq = 7023
count = 53
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.852478/7022, current 345.868805/7023: elapsed=16312.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.868805
last_received_ts = 345.868317
last_seq = 7023
current_ts = 345.885132
current_received_ts = 345.884613
current_seq = 7024
count = 54
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.868805/7023, current 345.885132/7024: elapsed=16323.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.885132
last_received_ts = 345.884613
last_seq = 7024
current_ts = 345.901428
current_received_ts = 345.900940
current_seq = 7025
count = 55
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.885132/7024, current 345.901428/7025: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.901428
last_received_ts = 345.900940
last_seq = 7025
current_ts = 345.917755
current_received_ts = 345.917206
current_seq = 7026
count = 56
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.901428/7025, current 345.917755/7026: elapsed=16315.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.917755
last_received_ts = 345.917206
last_seq = 7026
current_ts = 345.934082
current_received_ts = 345.933594
current_seq = 7027
count = 57
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.917755/7026, current 345.934082/7027: elapsed=16320.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.934082
last_received_ts = 345.933594
last_seq = 7027
current_ts = 345.950378
current_received_ts = 345.949890
current_seq = 7028
count = 58
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.934082/7027, current 345.950378/7028: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.950378
last_received_ts = 345.949890
last_seq = 7028
current_ts = 345.966705
current_received_ts = 345.966217
current_seq = 7029
count = 59
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.950378/7028, current 345.966705/7029: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.966705
last_received_ts = 345.966217
last_seq = 7029
current_ts = 345.983032
current_received_ts = 345.982513
current_seq = 7030
count = 60
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.966705/7029, current 345.983032/7030: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.983032
last_received_ts = 345.982513
last_seq = 7030
current_ts = 345.999329
current_received_ts = 345.998840
current_seq = 7031
count = 61
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.983032/7030, current 345.999329/7031: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 345.999329
last_received_ts = 345.998840
last_seq = 7031
current_ts = 346.015656
current_received_ts = 346.015228
current_seq = 7032
count = 62
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 345.999329/7031, current 346.015656/7032: elapsed=16313.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.015656
last_received_ts = 346.015228
last_seq = 7032
current_ts = 346.031982
current_received_ts = 346.031525
current_seq = 7033
count = 63
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.015656/7032, current 346.031982/7033: elapsed=16323.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.031982
last_received_ts = 346.031525
last_seq = 7033
current_ts = 346.048279
current_received_ts = 346.047852
current_seq = 7034
count = 64
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.031982/7033, current 346.048279/7034: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.048279
last_received_ts = 346.047852
last_seq = 7034
current_ts = 346.064606
current_received_ts = 346.064148
current_seq = 7035
count = 65
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.048279/7034, current 346.064606/7035: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.064606
last_received_ts = 346.064148
last_seq = 7035
current_ts = 346.080933
current_received_ts = 346.080414
current_seq = 7036
count = 66
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.064606/7035, current 346.080933/7036: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.080933
last_received_ts = 346.080414
last_seq = 7036
current_ts = 346.097229
current_received_ts = 346.096741
current_seq = 7037
count = 67
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.080933/7036, current 346.097229/7037: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.097229
last_received_ts = 346.096741
last_seq = 7037
current_ts = 346.113556
current_received_ts = 346.113098
current_seq = 7038
count = 68
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.097229/7037, current 346.113556/7038: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.113556
last_received_ts = 346.113098
last_seq = 7038
current_ts = 346.129883
current_received_ts = 346.129364
current_seq = 7039
count = 69
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.113556/7038, current 346.129883/7039: elapsed=16317.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.129883
last_received_ts = 346.129364
last_seq = 7039
current_ts = 346.146210
current_received_ts = 346.145691
current_seq = 7040
count = 70
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.129883/7039, current 346.146210/7040: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.146210
last_received_ts = 346.145691
last_seq = 7040
current_ts = 346.162506
current_received_ts = 346.162079
current_seq = 7041
count = 71
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.146210/7040, current 346.162506/7041: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.162506
last_received_ts = 346.162079
last_seq = 7041
current_ts = 346.178833
current_received_ts = 346.178345
current_seq = 7042
count = 72
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.162506/7041, current 346.178833/7042: elapsed=16316.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.178833
last_received_ts = 346.178345
last_seq = 7042
current_ts = 346.195160
current_received_ts = 346.194641
current_seq = 7043
count = 73
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.178833/7042, current 346.195160/7043: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.195160
last_received_ts = 346.194641
last_seq = 7043
current_ts = 346.211456
current_received_ts = 346.210968
current_seq = 7044
count = 74
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.195160/7043, current 346.211456/7044: elapsed=16309.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.211456
last_received_ts = 346.210968
last_seq = 7044
current_ts = 346.227783
current_received_ts = 346.227325
current_seq = 7045
count = 75
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.211456/7044, current 346.227783/7045: elapsed=16328.0us expected=16268.0us +- 81.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.227783
last_received_ts = 346.227325
last_seq = 7045
current_ts = 346.244110
current_received_ts = 346.243591
current_seq = 7046
count = 76
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.227783/7045, current 346.244110/7046: elapsed=16315.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.244110
last_received_ts = 346.243591
last_seq = 7046
current_ts = 346.260406
current_received_ts = 346.259918
current_seq = 7047
count = 77
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.244110/7046, current 346.260406/7047: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.260406
last_received_ts = 346.259918
last_seq = 7047
current_ts = 346.276733
current_received_ts = 346.276215
current_seq = 7048
count = 78
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.260406/7047, current 346.276733/7048: elapsed=16320.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.276733
last_received_ts = 346.276215
last_seq = 7048
current_ts = 346.293060
current_received_ts = 346.292542
current_seq = 7049
count = 79
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.276733/7048, current 346.293060/7049: elapsed=16318.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.293060
last_received_ts = 346.292542
last_seq = 7049
current_ts = 346.309357
current_received_ts = 346.308868
current_seq = 7050
count = 80
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.293060/7049, current 346.309357/7050: elapsed=16313.0us expected=16268.0us +- 81.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.309357
last_received_ts = 346.308868
last_seq = 7050
current_ts = 346.325684
current_received_ts = 346.325226
current_seq = 7051
count = 81
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.309357/7050, current 346.325684/7051: elapsed=16325.0us expected=16268.0us +- 81.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 346.325684
last_received_ts = 346.325226
last_seq = 7051
current_ts = 346.342072
current_received_ts = 346.341553
current_seq = 7052
count = 82
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 346.325684/7051, current 346.342072/7052: elapsed=16363.0us expected=16268.0us +- 81.3us, error 0.6%
(kms_flip:8259) DEBUG: inconsistent flip ts/seq: last 346.325684/7051, current 346.342072/7052: elapsed=16363.0us expected=16268.0us
(kms_flip:8259) DEBUG: expected 13149, counted 82, encoder type 2
(kms_flip:8259) DEBUG: dropped frames, expected 13149, counted 82, encoder type 2
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:8259) igt_core-INFO: Stack trace:
(kms_flip:8259) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:8259) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:8259) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:8259) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:8259) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:8259) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:8259) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:8259) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AD-HDMI-A6-DP4: FAIL (5.080s)
Starting dynamic subtest: BC-HDMI-A6-DP4
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest BC-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:8259) DEBUG: flip ts/seq: last 351.346558/4628, current 351.363068/4629: elapsed=16499.0us expected=16458.2us +- 82.3us, error 0.2%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.363068
last_received_ts = 351.362610
last_seq = 4629
current_ts = 351.379578
current_received_ts = 351.379150
current_seq = 4630
count = 83
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.363068/4629, current 351.379578/4630: elapsed=16510.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.379578
last_received_ts = 351.379150
last_seq = 4630
current_ts = 351.396057
current_received_ts = 351.395630
current_seq = 4631
count = 84
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.379578/4630, current 351.396057/4631: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.396057
last_received_ts = 351.395630
last_seq = 4631
current_ts = 351.412567
current_received_ts = 351.412201
current_seq = 4632
count = 85
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.396057/4631, current 351.412567/4632: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.412567
last_received_ts = 351.412201
last_seq = 4632
current_ts = 351.429077
current_received_ts = 351.428650
current_seq = 4633
count = 86
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.412567/4632, current 351.429077/4633: elapsed=16505.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.429077
last_received_ts = 351.428650
last_seq = 4633
current_ts = 351.445587
current_received_ts = 351.445160
current_seq = 4634
count = 87
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.429077/4633, current 351.445587/4634: elapsed=16503.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.445587
last_received_ts = 351.445160
last_seq = 4634
current_ts = 351.462097
current_received_ts = 351.461670
current_seq = 4635
count = 88
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.445587/4634, current 351.462097/4635: elapsed=16509.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.462097
last_received_ts = 351.461670
last_seq = 4635
current_ts = 351.478607
current_received_ts = 351.478180
current_seq = 4636
count = 89
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.462097/4635, current 351.478607/4636: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.478607
last_received_ts = 351.478180
last_seq = 4636
current_ts = 351.495117
current_received_ts = 351.494690
current_seq = 4637
count = 90
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.478607/4636, current 351.495117/4637: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.495117
last_received_ts = 351.494690
last_seq = 4637
current_ts = 351.511627
current_received_ts = 351.511169
current_seq = 4638
count = 91
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.495117/4637, current 351.511627/4638: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.511627
last_received_ts = 351.511169
last_seq = 4638
current_ts = 351.528137
current_received_ts = 351.527679
current_seq = 4639
count = 92
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.511627/4638, current 351.528137/4639: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.528137
last_received_ts = 351.527679
last_seq = 4639
current_ts = 351.544617
current_received_ts = 351.544189
current_seq = 4640
count = 93
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.528137/4639, current 351.544617/4640: elapsed=16501.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.544617
last_received_ts = 351.544189
last_seq = 4640
current_ts = 351.561127
current_received_ts = 351.560699
current_seq = 4641
count = 94
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.544617/4640, current 351.561127/4641: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.561127
last_received_ts = 351.560699
last_seq = 4641
current_ts = 351.577637
current_received_ts = 351.577179
current_seq = 4642
count = 95
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.561127/4641, current 351.577637/4642: elapsed=16511.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.577637
last_received_ts = 351.577179
last_seq = 4642
current_ts = 351.594147
current_received_ts = 351.593719
current_seq = 4643
count = 96
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.577637/4642, current 351.594147/4643: elapsed=16502.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.594147
last_received_ts = 351.593719
last_seq = 4643
current_ts = 351.610657
current_received_ts = 351.610199
current_seq = 4644
count = 97
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.594147/4643, current 351.610657/4644: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.610657
last_received_ts = 351.610199
last_seq = 4644
current_ts = 351.627167
current_received_ts = 351.626709
current_seq = 4645
count = 98
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.610657/4644, current 351.627167/4645: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.627167
last_received_ts = 351.626709
last_seq = 4645
current_ts = 351.643646
current_received_ts = 351.643158
current_seq = 4646
count = 99
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.627167/4645, current 351.643646/4646: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.643646
last_received_ts = 351.643158
last_seq = 4646
current_ts = 351.660156
current_received_ts = 351.659729
current_seq = 4647
count = 100
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.643646/4646, current 351.660156/4647: elapsed=16505.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.660156
last_received_ts = 351.659729
last_seq = 4647
current_ts = 351.676666
current_received_ts = 351.676239
current_seq = 4648
count = 101
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.660156/4647, current 351.676666/4648: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.676666
last_received_ts = 351.676239
last_seq = 4648
current_ts = 351.693176
current_received_ts = 351.692688
current_seq = 4649
count = 102
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.676666/4648, current 351.693176/4649: elapsed=16509.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.693176
last_received_ts = 351.692688
last_seq = 4649
current_ts = 351.709686
current_received_ts = 351.709229
current_seq = 4650
count = 103
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.693176/4649, current 351.709686/4650: elapsed=16511.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.709686
last_received_ts = 351.709229
last_seq = 4650
current_ts = 351.726196
current_received_ts = 351.725677
current_seq = 4651
count = 104
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.709686/4650, current 351.726196/4651: elapsed=16501.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.726196
last_received_ts = 351.725677
last_seq = 4651
current_ts = 351.742676
current_received_ts = 351.742218
current_seq = 4652
count = 105
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.726196/4651, current 351.742676/4652: elapsed=16500.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.742676
last_received_ts = 351.742218
last_seq = 4652
current_ts = 351.759186
current_received_ts = 351.758698
current_seq = 4653
count = 106
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.742676/4652, current 351.759186/4653: elapsed=16510.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.759186
last_received_ts = 351.758698
last_seq = 4653
current_ts = 351.775696
current_received_ts = 351.775238
current_seq = 4654
count = 107
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.759186/4653, current 351.775696/4654: elapsed=16511.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.775696
last_received_ts = 351.775238
last_seq = 4654
current_ts = 351.792206
current_received_ts = 351.791718
current_seq = 4655
count = 108
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.775696/4654, current 351.792206/4655: elapsed=16502.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.792206
last_received_ts = 351.791718
last_seq = 4655
current_ts = 351.808716
current_received_ts = 351.808228
current_seq = 4656
count = 109
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.792206/4655, current 351.808716/4656: elapsed=16505.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.808716
last_received_ts = 351.808228
last_seq = 4656
current_ts = 351.825226
current_received_ts = 351.824738
current_seq = 4657
count = 110
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.808716/4656, current 351.825226/4657: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.825226
last_received_ts = 351.824738
last_seq = 4657
current_ts = 351.841736
current_received_ts = 351.841217
current_seq = 4658
count = 111
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.825226/4657, current 351.841736/4658: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.841736
last_received_ts = 351.841217
last_seq = 4658
current_ts = 351.858246
current_received_ts = 351.857727
current_seq = 4659
count = 112
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.841736/4658, current 351.858246/4659: elapsed=16509.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.858246
last_received_ts = 351.857727
last_seq = 4659
current_ts = 351.874725
current_received_ts = 351.874329
current_seq = 4660
count = 113
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.858246/4659, current 351.874725/4660: elapsed=16501.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.874725
last_received_ts = 351.874329
last_seq = 4660
current_ts = 351.891235
current_received_ts = 351.890808
current_seq = 4661
count = 114
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.874725/4660, current 351.891235/4661: elapsed=16510.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.891235
last_received_ts = 351.890808
last_seq = 4661
current_ts = 351.907745
current_received_ts = 351.907288
current_seq = 4662
count = 115
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.891235/4661, current 351.907745/4662: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.907745
last_received_ts = 351.907288
last_seq = 4662
current_ts = 351.924255
current_received_ts = 351.923828
current_seq = 4663
count = 116
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.907745/4662, current 351.924255/4663: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.924255
last_received_ts = 351.923828
last_seq = 4663
current_ts = 351.940765
current_received_ts = 351.940216
current_seq = 4664
count = 117
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.924255/4663, current 351.940765/4664: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.940765
last_received_ts = 351.940216
last_seq = 4664
current_ts = 351.957275
current_received_ts = 351.956848
current_seq = 4665
count = 118
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.940765/4664, current 351.957275/4665: elapsed=16509.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.957275
last_received_ts = 351.956848
last_seq = 4665
current_ts = 351.973785
current_received_ts = 351.973297
current_seq = 4666
count = 119
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.957275/4665, current 351.973785/4666: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.973785
last_received_ts = 351.973297
last_seq = 4666
current_ts = 351.990295
current_received_ts = 351.989838
current_seq = 4667
count = 120
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.973785/4666, current 351.990295/4667: elapsed=16500.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 351.990295
last_received_ts = 351.989838
last_seq = 4667
current_ts = 352.006775
current_received_ts = 352.006317
current_seq = 4668
count = 121
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 351.990295/4667, current 352.006775/4668: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.006775
last_received_ts = 352.006317
last_seq = 4668
current_ts = 352.023285
current_received_ts = 352.022858
current_seq = 4669
count = 122
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.006775/4668, current 352.023285/4669: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.023285
last_received_ts = 352.022858
last_seq = 4669
current_ts = 352.039795
current_received_ts = 352.039368
current_seq = 4670
count = 123
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.023285/4669, current 352.039795/4670: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.039795
last_received_ts = 352.039368
last_seq = 4670
current_ts = 352.056305
current_received_ts = 352.055878
current_seq = 4671
count = 124
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.039795/4670, current 352.056305/4671: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.056305
last_received_ts = 352.055878
last_seq = 4671
current_ts = 352.072815
current_received_ts = 352.072418
current_seq = 4672
count = 125
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.056305/4671, current 352.072815/4672: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.072815
last_received_ts = 352.072418
last_seq = 4672
current_ts = 352.089325
current_received_ts = 352.088898
current_seq = 4673
count = 126
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.072815/4672, current 352.089325/4673: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.089325
last_received_ts = 352.088898
last_seq = 4673
current_ts = 352.105835
current_received_ts = 352.105408
current_seq = 4674
count = 127
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.089325/4673, current 352.105835/4674: elapsed=16509.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.105835
last_received_ts = 352.105408
last_seq = 4674
current_ts = 352.122345
current_received_ts = 352.121887
current_seq = 4675
count = 128
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.105835/4674, current 352.122345/4675: elapsed=16502.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.122345
last_received_ts = 352.121887
last_seq = 4675
current_ts = 352.138824
current_received_ts = 352.138397
current_seq = 4676
count = 129
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.122345/4675, current 352.138824/4676: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.138824
last_received_ts = 352.138397
last_seq = 4676
current_ts = 352.155334
current_received_ts = 352.154907
current_seq = 4677
count = 130
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.138824/4676, current 352.155334/4677: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.155334
last_received_ts = 352.154907
last_seq = 4677
current_ts = 352.171844
current_received_ts = 352.171417
current_seq = 4678
count = 131
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.155334/4677, current 352.171844/4678: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.171844
last_received_ts = 352.171417
last_seq = 4678
current_ts = 352.188354
current_received_ts = 352.187897
current_seq = 4679
count = 132
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.171844/4678, current 352.188354/4679: elapsed=16503.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.188354
last_received_ts = 352.187897
last_seq = 4679
current_ts = 352.204865
current_received_ts = 352.204407
current_seq = 4680
count = 133
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.188354/4679, current 352.204865/4680: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.204865
last_received_ts = 352.204407
last_seq = 4680
current_ts = 352.221375
current_received_ts = 352.220917
current_seq = 4681
count = 134
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.204865/4680, current 352.221375/4681: elapsed=16508.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.221375
last_received_ts = 352.220917
last_seq = 4681
current_ts = 352.237885
current_received_ts = 352.237427
current_seq = 4682
count = 135
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.221375/4681, current 352.237885/4682: elapsed=16504.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.237885
last_received_ts = 352.237427
last_seq = 4682
current_ts = 352.254364
current_received_ts = 352.253937
current_seq = 4683
count = 136
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.237885/4682, current 352.254364/4683: elapsed=16506.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.254364
last_received_ts = 352.253937
last_seq = 4683
current_ts = 352.270874
current_received_ts = 352.270447
current_seq = 4684
count = 137
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.254364/4683, current 352.270874/4684: elapsed=16499.0us expected=16458.2us +- 82.3us, error 0.2%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.270874
last_received_ts = 352.270447
last_seq = 4684
current_ts = 352.287384
current_received_ts = 352.286957
current_seq = 4685
count = 138
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.270874/4684, current 352.287384/4685: elapsed=16513.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.287384
last_received_ts = 352.286957
last_seq = 4685
current_ts = 352.303894
current_received_ts = 352.303467
current_seq = 4686
count = 139
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.287384/4685, current 352.303894/4686: elapsed=16505.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.303894
last_received_ts = 352.303467
last_seq = 4686
current_ts = 352.320404
current_received_ts = 352.319977
current_seq = 4687
count = 140
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.303894/4686, current 352.320404/4687: elapsed=16507.0us expected=16458.2us +- 82.3us, error 0.3%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.320404
last_received_ts = 352.319977
last_seq = 4687
current_ts = 352.336914
current_received_ts = 352.336487
current_seq = 4688
count = 141
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.320404/4687, current 352.336914/4688: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.336914
last_received_ts = 352.336487
last_seq = 4688
current_ts = 352.353455
current_received_ts = 352.353058
current_seq = 4689
count = 142
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.336914/4688, current 352.353455/4689: elapsed=16527.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.353455
last_received_ts = 352.353058
last_seq = 4689
current_ts = 352.369965
current_received_ts = 352.369537
current_seq = 4690
count = 143
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.353455/4689, current 352.369965/4690: elapsed=16522.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.369965
last_received_ts = 352.369537
last_seq = 4690
current_ts = 352.386505
current_received_ts = 352.386078
current_seq = 4691
count = 144
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.369965/4690, current 352.386505/4691: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.386505
last_received_ts = 352.386078
last_seq = 4691
current_ts = 352.403015
current_received_ts = 352.402588
current_seq = 4692
count = 145
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.386505/4691, current 352.403015/4692: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.403015
last_received_ts = 352.402588
last_seq = 4692
current_ts = 352.419556
current_received_ts = 352.419159
current_seq = 4693
count = 146
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.403015/4692, current 352.419556/4693: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.419556
last_received_ts = 352.419159
last_seq = 4693
current_ts = 352.436066
current_received_ts = 352.435638
current_seq = 4694
count = 147
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.419556/4693, current 352.436066/4694: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.436066
last_received_ts = 352.435638
last_seq = 4694
current_ts = 352.452606
current_received_ts = 352.452209
current_seq = 4695
count = 148
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.436066/4694, current 352.452606/4695: elapsed=16523.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.452606
last_received_ts = 352.452209
last_seq = 4695
current_ts = 352.469116
current_received_ts = 352.468689
current_seq = 4696
count = 149
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.452606/4695, current 352.469116/4696: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.469116
last_received_ts = 352.468689
last_seq = 4696
current_ts = 352.485657
current_received_ts = 352.485260
current_seq = 4697
count = 150
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.469116/4696, current 352.485657/4697: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.485657
last_received_ts = 352.485260
last_seq = 4697
current_ts = 352.502167
current_received_ts = 352.501740
current_seq = 4698
count = 151
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.485657/4697, current 352.502167/4698: elapsed=16523.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.502167
last_received_ts = 352.501740
last_seq = 4698
current_ts = 352.518707
current_received_ts = 352.518280
current_seq = 4699
count = 152
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.502167/4698, current 352.518707/4699: elapsed=16521.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.518707
last_received_ts = 352.518280
last_seq = 4699
current_ts = 352.535217
current_received_ts = 352.534790
current_seq = 4700
count = 153
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.518707/4699, current 352.535217/4700: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.535217
last_received_ts = 352.534790
last_seq = 4700
current_ts = 352.551758
current_received_ts = 352.551270
current_seq = 4701
count = 154
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.535217/4700, current 352.551758/4701: elapsed=16531.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.551758
last_received_ts = 352.551270
last_seq = 4701
current_ts = 352.568268
current_received_ts = 352.567841
current_seq = 4702
count = 155
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.551758/4701, current 352.568268/4702: elapsed=16523.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.568268
last_received_ts = 352.567841
last_seq = 4702
current_ts = 352.584778
current_received_ts = 352.584381
current_seq = 4703
count = 156
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.568268/4702, current 352.584778/4703: elapsed=16516.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.584778
last_received_ts = 352.584381
last_seq = 4703
current_ts = 352.601318
current_received_ts = 352.600891
current_seq = 4704
count = 157
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.584778/4703, current 352.601318/4704: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.601318
last_received_ts = 352.600891
last_seq = 4704
current_ts = 352.617859
current_received_ts = 352.617401
current_seq = 4705
count = 158
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.601318/4704, current 352.617859/4705: elapsed=16529.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.617859
last_received_ts = 352.617401
last_seq = 4705
current_ts = 352.634369
current_received_ts = 352.633942
current_seq = 4706
count = 159
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.617859/4705, current 352.634369/4706: elapsed=16529.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.634369
last_received_ts = 352.633942
last_seq = 4706
current_ts = 352.650909
current_received_ts = 352.650452
current_seq = 4707
count = 160
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.634369/4706, current 352.650909/4707: elapsed=16522.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.650909
last_received_ts = 352.650452
last_seq = 4707
current_ts = 352.667419
current_received_ts = 352.666992
current_seq = 4708
count = 161
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.650909/4707, current 352.667419/4708: elapsed=16528.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.667419
last_received_ts = 352.666992
last_seq = 4708
current_ts = 352.683960
current_received_ts = 352.683533
current_seq = 4709
count = 162
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.667419/4708, current 352.683960/4709: elapsed=16527.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.683960
last_received_ts = 352.683533
last_seq = 4709
current_ts = 352.700470
current_received_ts = 352.700073
current_seq = 4710
count = 163
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.683960/4709, current 352.700470/4710: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.700470
last_received_ts = 352.700073
last_seq = 4710
current_ts = 352.717010
current_received_ts = 352.716553
current_seq = 4711
count = 164
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.700470/4710, current 352.717010/4711: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.717010
last_received_ts = 352.716553
last_seq = 4711
current_ts = 352.733521
current_received_ts = 352.733093
current_seq = 4712
count = 165
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.717010/4711, current 352.733521/4712: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.733521
last_received_ts = 352.733093
last_seq = 4712
current_ts = 352.750061
current_received_ts = 352.749603
current_seq = 4713
count = 166
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.733521/4712, current 352.750061/4713: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.750061
last_received_ts = 352.749603
last_seq = 4713
current_ts = 352.766571
current_received_ts = 352.766174
current_seq = 4714
count = 167
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.750061/4713, current 352.766571/4714: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.766571
last_received_ts = 352.766174
last_seq = 4714
current_ts = 352.783112
current_received_ts = 352.782654
current_seq = 4715
count = 168
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.766571/4714, current 352.783112/4715: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.783112
last_received_ts = 352.782654
last_seq = 4715
current_ts = 352.799622
current_received_ts = 352.799164
current_seq = 4716
count = 169
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.783112/4715, current 352.799622/4716: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.799622
last_received_ts = 352.799164
last_seq = 4716
current_ts = 352.816162
current_received_ts = 352.815704
current_seq = 4717
count = 170
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.799622/4716, current 352.816162/4717: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.816162
last_received_ts = 352.815704
last_seq = 4717
current_ts = 352.832672
current_received_ts = 352.832306
current_seq = 4718
count = 171
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.816162/4717, current 352.832672/4718: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.832672
last_received_ts = 352.832306
last_seq = 4718
current_ts = 352.849213
current_received_ts = 352.848755
current_seq = 4719
count = 172
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.832672/4718, current 352.849213/4719: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.849213
last_received_ts = 352.848755
last_seq = 4719
current_ts = 352.865723
current_received_ts = 352.865295
current_seq = 4720
count = 173
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.849213/4719, current 352.865723/4720: elapsed=16519.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.865723
last_received_ts = 352.865295
last_seq = 4720
current_ts = 352.882263
current_received_ts = 352.881805
current_seq = 4721
count = 174
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.865723/4720, current 352.882263/4721: elapsed=16533.0us expected=16458.2us +- 82.3us, error 0.5%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.882263
last_received_ts = 352.881805
last_seq = 4721
current_ts = 352.898773
current_received_ts = 352.898285
current_seq = 4722
count = 175
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.882263/4721, current 352.898773/4722: elapsed=16530.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.898773
last_received_ts = 352.898285
last_seq = 4722
current_ts = 352.915314
current_received_ts = 352.914856
current_seq = 4723
count = 176
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.898773/4722, current 352.915314/4723: elapsed=16519.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.915314
last_received_ts = 352.914856
last_seq = 4723
current_ts = 352.931824
current_received_ts = 352.931396
current_seq = 4724
count = 177
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.915314/4723, current 352.931824/4724: elapsed=16519.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.931824
last_received_ts = 352.931396
last_seq = 4724
current_ts = 352.948364
current_received_ts = 352.947906
current_seq = 4725
count = 178
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.931824/4724, current 352.948364/4725: elapsed=16534.0us expected=16458.2us +- 82.3us, error 0.5%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.948364
last_received_ts = 352.947906
last_seq = 4725
current_ts = 352.964874
current_received_ts = 352.964447
current_seq = 4726
count = 179
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.948364/4725, current 352.964874/4726: elapsed=16523.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.964874
last_received_ts = 352.964447
last_seq = 4726
current_ts = 352.981415
current_received_ts = 352.980957
current_seq = 4727
count = 180
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.964874/4726, current 352.981415/4727: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.981415
last_received_ts = 352.980957
last_seq = 4727
current_ts = 352.997925
current_received_ts = 352.997498
current_seq = 4728
count = 181
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.981415/4727, current 352.997925/4728: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 352.997925
last_received_ts = 352.997498
last_seq = 4728
current_ts = 353.014465
current_received_ts = 353.014038
current_seq = 4729
count = 182
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 352.997925/4728, current 353.014465/4729: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.014465
last_received_ts = 353.014038
last_seq = 4729
current_ts = 353.030975
current_received_ts = 353.030548
current_seq = 4730
count = 183
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.014465/4729, current 353.030975/4730: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.030975
last_received_ts = 353.030548
last_seq = 4730
current_ts = 353.047485
current_received_ts = 353.047089
current_seq = 4731
count = 184
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.030975/4730, current 353.047485/4731: elapsed=16523.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.047485
last_received_ts = 353.047089
last_seq = 4731
current_ts = 353.064026
current_received_ts = 353.063568
current_seq = 4732
count = 185
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.047485/4731, current 353.064026/4732: elapsed=16527.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.064026
last_received_ts = 353.063568
last_seq = 4732
current_ts = 353.080536
current_received_ts = 353.080170
current_seq = 4733
count = 186
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.064026/4732, current 353.080536/4733: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.080536
last_received_ts = 353.080170
last_seq = 4733
current_ts = 353.097076
current_received_ts = 353.096588
current_seq = 4734
count = 187
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.080536/4733, current 353.097076/4734: elapsed=16524.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.097076
last_received_ts = 353.096588
last_seq = 4734
current_ts = 353.113586
current_received_ts = 353.113129
current_seq = 4735
count = 188
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.097076/4734, current 353.113586/4735: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.113586
last_received_ts = 353.113129
last_seq = 4735
current_ts = 353.130127
current_received_ts = 353.129639
current_seq = 4736
count = 189
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.113586/4735, current 353.130127/4736: elapsed=16525.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.130127
last_received_ts = 353.129639
last_seq = 4736
current_ts = 353.146637
current_received_ts = 353.146179
current_seq = 4737
count = 190
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.130127/4736, current 353.146637/4737: elapsed=16522.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.146637
last_received_ts = 353.146179
last_seq = 4737
current_ts = 353.163177
current_received_ts = 353.162689
current_seq = 4738
count = 191
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.146637/4737, current 353.163177/4738: elapsed=16528.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.163177
last_received_ts = 353.162689
last_seq = 4738
current_ts = 353.179688
current_received_ts = 353.179230
current_seq = 4739
count = 192
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.163177/4738, current 353.179688/4739: elapsed=16520.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.179688
last_received_ts = 353.179230
last_seq = 4739
current_ts = 353.196228
current_received_ts = 353.195740
current_seq = 4740
count = 193
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.179688/4739, current 353.196228/4740: elapsed=16531.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.196228
last_received_ts = 353.195740
last_seq = 4740
current_ts = 353.212769
current_received_ts = 353.212219
current_seq = 4741
count = 194
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.196228/4740, current 353.212769/4741: elapsed=16527.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.212769
last_received_ts = 353.212219
last_seq = 4741
current_ts = 353.229279
current_received_ts = 353.228790
current_seq = 4742
count = 195
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.212769/4741, current 353.229279/4742: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.229279
last_received_ts = 353.228790
last_seq = 4742
current_ts = 353.245789
current_received_ts = 353.245331
current_seq = 4743
count = 196
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.229279/4742, current 353.245789/4743: elapsed=16522.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.245789
last_received_ts = 353.245331
last_seq = 4743
current_ts = 353.262329
current_received_ts = 353.261871
current_seq = 4744
count = 197
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.245789/4743, current 353.262329/4744: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.262329
last_received_ts = 353.261871
last_seq = 4744
current_ts = 353.278839
current_received_ts = 353.278412
current_seq = 4745
count = 198
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.262329/4744, current 353.278839/4745: elapsed=16520.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.278839
last_received_ts = 353.278412
last_seq = 4745
current_ts = 353.295380
current_received_ts = 353.294952
current_seq = 4746
count = 199
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.278839/4745, current 353.295380/4746: elapsed=16529.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.295380
last_received_ts = 353.294952
last_seq = 4746
current_ts = 353.311890
current_received_ts = 353.311462
current_seq = 4747
count = 200
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.295380/4746, current 353.311890/4747: elapsed=16526.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.311890
last_received_ts = 353.311462
last_seq = 4747
current_ts = 353.328430
current_received_ts = 353.328033
current_seq = 4748
count = 201
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.311890/4747, current 353.328430/4748: elapsed=16532.0us expected=16458.2us +- 82.3us, error 0.4%
(kms_flip:8259) DEBUG: name = flip
last_ts = 353.328430
last_received_ts = 353.328033
last_seq = 4748
current_ts = 353.344971
current_received_ts = 353.344543
current_seq = 4749
count = 202
seq_step = 1
(kms_flip:8259) DEBUG: flip ts/seq: last 353.328430/4748, current 353.344971/4749: elapsed=16542.0us expected=16458.2us +- 82.3us, error 0.5%
(kms_flip:8259) DEBUG: inconsistent flip ts/seq: last 353.328430/4748, current 353.344971/4749: elapsed=16542.0us expected=16458.2us
(kms_flip:8259) DEBUG: expected 12997, counted 202, encoder type 2
(kms_flip:8259) DEBUG: dropped frames, expected 12997, counted 202, encoder type 2
(kms_flip:8259) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:8259) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:8259) igt_core-INFO: Stack trace:
(kms_flip:8259) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:8259) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:8259) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:8259) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:8259) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:8259) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:8259) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:8259) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest BC-HDMI-A6-DP4: FAIL (7.473s)
Starting dynamic subtest: BD-HDMI-A6-DP4
Dynamic subtest BD-HDMI-A6-DP4: SUCCESS (5.681s)
Starting dynamic subtest: CD-HDMI-A6-DP4
Dynamic subtest CD-HDMI-A6-DP4: SUCCESS (5.657s)
Subtest 2x-plain-flip-fb-recreate: FAIL (28.498s)