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

shard-bmg-5

IGT-Version: 1.30-g2c9202bdb (x86_64) (Linux: 6.14.0-rc2-xe+ x86_64)

Using IGT_SRANDOM=1739420217 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16255.8us +- 17.295us accuracy 0.32%
vblank interval differs from modeline! expected 16666.7us, measured 16256us +- 17.295us, difference 410.9us (23.8 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 AB-DP2-HDMI-A3: FAIL (7.385s)
Starting dynamic subtest: AC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16503.1us +- 1.289us accuracy 0.02%
vblank interval differs from modeline! expected 16666.7us, measured 16503us +- 1.289us, difference 163.6us (126.9 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-DP2-HDMI-A3: FAIL (9.757s)
Starting dynamic subtest: AD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16617.1us +- 5.247us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16617us +- 5.247us, difference 49.6us (9.5 sigma)
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.686s)
Starting dynamic subtest: BC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16638.2us +- 4.435us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16638us +- 4.435us, difference 28.4us (6.4 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.675s)
Starting dynamic subtest: BD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16651.0us +- 3.670us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 16651us +- 3.670us, difference 15.7us (4.3 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.646s)
Starting dynamic subtest: CD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16669.6us +- 1.711us accuracy 0.03%
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.639s)
Subtest 2x-plain-flip-ts-check: FAIL (39.832s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:7604) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7604) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7604) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7604) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:7604) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7604) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd3cf10, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd3cf10, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd4b870, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd4b870, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd8f660, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd8f660, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd81b60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) intel_allocator_simple-DEBUG: <ial: 0x61abebd81b60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7604) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7604) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:7604) DEBUG: No stale events found
(kms_flip:7604) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7604) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7604) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7604) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7604) INFO: Expected frametime: 16667us; measured 16255.8us +- 17.295us accuracy 0.32%
(kms_flip:7604) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16256us +- 17.295us, difference 410.9us (23.8 sigma)
(kms_flip:7604) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 281.702881
current_received_ts = 281.702301
current_seq = 11735
count = 0
seq_step = 1
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.702881
last_received_ts = 281.702301
last_seq = 11735
current_ts = 281.719116
current_received_ts = 281.718567
current_seq = 11736
count = 1
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.702881/11735, current 281.719116/11736: elapsed=16258.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.719116
last_received_ts = 281.718567
last_seq = 11736
current_ts = 281.735382
current_received_ts = 281.734772
current_seq = 11737
count = 2
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.719116/11736, current 281.735382/11737: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.735382
last_received_ts = 281.734772
last_seq = 11737
current_ts = 281.751648
current_received_ts = 281.751099
current_seq = 11738
count = 3
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.735382/11737, current 281.751648/11738: elapsed=16259.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.751648
last_received_ts = 281.751099
last_seq = 11738
current_ts = 281.767914
current_received_ts = 281.767334
current_seq = 11739
count = 4
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.751648/11738, current 281.767914/11739: elapsed=16263.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.767914
last_received_ts = 281.767334
last_seq = 11739
current_ts = 281.784149
current_received_ts = 281.783569
current_seq = 11740
count = 5
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.767914/11739, current 281.784149/11740: elapsed=16256.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.784149
last_received_ts = 281.783569
last_seq = 11740
current_ts = 281.800415
current_received_ts = 281.799835
current_seq = 11741
count = 6
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.784149/11740, current 281.800415/11741: elapsed=16263.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.800415
last_received_ts = 281.799835
last_seq = 11741
current_ts = 281.816681
current_received_ts = 281.816254
current_seq = 11742
count = 7
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.800415/11741, current 281.816681/11742: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.816681
last_received_ts = 281.816254
last_seq = 11742
current_ts = 281.832947
current_received_ts = 281.832458
current_seq = 11743
count = 8
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.816681/11742, current 281.832947/11743: elapsed=16273.0us expected=16255.8us +- 81.3us, error 0.1%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.832947
last_received_ts = 281.832458
last_seq = 11743
current_ts = 281.849213
current_received_ts = 281.848602
current_seq = 11744
count = 9
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.832947/11743, current 281.849213/11744: elapsed=16259.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.849213
last_received_ts = 281.848602
last_seq = 11744
current_ts = 281.865479
current_received_ts = 281.864868
current_seq = 11745
count = 10
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.849213/11744, current 281.865479/11745: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.865479
last_received_ts = 281.864868
last_seq = 11745
current_ts = 281.881744
current_received_ts = 281.881134
current_seq = 11746
count = 11
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.865479/11745, current 281.881744/11746: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.881744
last_received_ts = 281.881134
last_seq = 11746
current_ts = 281.898010
current_received_ts = 281.897400
current_seq = 11747
count = 12
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.881744/11746, current 281.898010/11747: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.898010
last_received_ts = 281.897400
last_seq = 11747
current_ts = 281.914276
current_received_ts = 281.913666
current_seq = 11748
count = 13
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.898010/11747, current 281.914276/11748: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.914276
last_received_ts = 281.913666
last_seq = 11748
current_ts = 281.930511
current_received_ts = 281.929901
current_seq = 11749
count = 14
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.914276/11748, current 281.930511/11749: elapsed=16263.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.930511
last_received_ts = 281.929901
last_seq = 11749
current_ts = 281.946777
current_received_ts = 281.946167
current_seq = 11750
count = 15
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.930511/11749, current 281.946777/11750: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.946777
last_received_ts = 281.946167
last_seq = 11750
current_ts = 281.963043
current_received_ts = 281.962433
current_seq = 11751
count = 16
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.946777/11750, current 281.963043/11751: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.963043
last_received_ts = 281.962433
last_seq = 11751
current_ts = 281.979309
current_received_ts = 281.978699
current_seq = 11752
count = 17
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.963043/11751, current 281.979309/11752: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.979309
last_received_ts = 281.978699
last_seq = 11752
current_ts = 281.995575
current_received_ts = 281.994965
current_seq = 11753
count = 18
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.979309/11752, current 281.995575/11753: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 281.995575
last_received_ts = 281.994965
last_seq = 11753
current_ts = 282.011841
current_received_ts = 282.011200
current_seq = 11754
count = 19
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 281.995575/11753, current 282.011841/11754: elapsed=16259.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.011841
last_received_ts = 282.011200
last_seq = 11754
current_ts = 282.028076
current_received_ts = 282.027466
current_seq = 11755
count = 20
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.011841/11754, current 282.028076/11755: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.028076
last_received_ts = 282.027466
last_seq = 11755
current_ts = 282.044342
current_received_ts = 282.043732
current_seq = 11756
count = 21
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.028076/11755, current 282.044342/11756: elapsed=16264.0us expected=16255.8us +- 81.3us, error 0.1%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.044342
last_received_ts = 282.043732
last_seq = 11756
current_ts = 282.060608
current_received_ts = 282.060028
current_seq = 11757
count = 22
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.044342/11756, current 282.060608/11757: elapsed=16257.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.060608
last_received_ts = 282.060028
last_seq = 11757
current_ts = 282.076874
current_received_ts = 282.076324
current_seq = 11758
count = 23
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.060608/11757, current 282.076874/11758: elapsed=16266.0us expected=16255.8us +- 81.3us, error 0.1%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.076874
last_received_ts = 282.076324
last_seq = 11758
current_ts = 282.093140
current_received_ts = 282.092529
current_seq = 11759
count = 24
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.076874/11758, current 282.093140/11759: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.093140
last_received_ts = 282.092529
last_seq = 11759
current_ts = 282.109406
current_received_ts = 282.108795
current_seq = 11760
count = 25
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.093140/11759, current 282.109406/11760: elapsed=16257.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.109406
last_received_ts = 282.108795
last_seq = 11760
current_ts = 282.125671
current_received_ts = 282.125031
current_seq = 11761
count = 26
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.109406/11760, current 282.125671/11761: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.125671
last_received_ts = 282.125031
last_seq = 11761
current_ts = 282.141937
current_received_ts = 282.141327
current_seq = 11762
count = 27
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.125671/11761, current 282.141937/11762: elapsed=16266.0us expected=16255.8us +- 81.3us, error 0.1%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.141937
last_received_ts = 282.141327
last_seq = 11762
current_ts = 282.158173
current_received_ts = 282.157562
current_seq = 11763
count = 28
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.141937/11762, current 282.158173/11763: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.158173
last_received_ts = 282.157562
last_seq = 11763
current_ts = 282.174438
current_received_ts = 282.173828
current_seq = 11764
count = 29
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.158173/11763, current 282.174438/11764: elapsed=16259.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.174438
last_received_ts = 282.173828
last_seq = 11764
current_ts = 282.190704
current_received_ts = 282.190094
current_seq = 11765
count = 30
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.174438/11764, current 282.190704/11765: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.190704
last_received_ts = 282.190094
last_seq = 11765
current_ts = 282.206970
current_received_ts = 282.206360
current_seq = 11766
count = 31
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.190704/11765, current 282.206970/11766: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.206970
last_received_ts = 282.206360
last_seq = 11766
current_ts = 282.223236
current_received_ts = 282.222626
current_seq = 11767
count = 32
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.206970/11766, current 282.223236/11767: elapsed=16263.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.223236
last_received_ts = 282.222626
last_seq = 11767
current_ts = 282.239502
current_received_ts = 282.238892
current_seq = 11768
count = 33
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.223236/11767, current 282.239502/11768: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.239502
last_received_ts = 282.238892
last_seq = 11768
current_ts = 282.255737
current_received_ts = 282.255157
current_seq = 11769
count = 34
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.239502/11768, current 282.255737/11769: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.255737
last_received_ts = 282.255157
last_seq = 11769
current_ts = 282.272003
current_received_ts = 282.271393
current_seq = 11770
count = 35
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.255737/11769, current 282.272003/11770: elapsed=16263.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.272003
last_received_ts = 282.271393
last_seq = 11770
current_ts = 282.288269
current_received_ts = 282.287659
current_seq = 11771
count = 36
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.272003/11770, current 282.288269/11771: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.288269
last_received_ts = 282.287659
last_seq = 11771
current_ts = 282.304535
current_received_ts = 282.303925
current_seq = 11772
count = 37
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.288269/11771, current 282.304535/11772: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.304535
last_received_ts = 282.303925
last_seq = 11772
current_ts = 282.320801
current_received_ts = 282.320190
current_seq = 11773
count = 38
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.304535/11772, current 282.320801/11773: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.320801
last_received_ts = 282.320190
last_seq = 11773
current_ts = 282.337067
current_received_ts = 282.336456
current_seq = 11774
count = 39
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.320801/11773, current 282.337067/11774: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.337067
last_received_ts = 282.336456
last_seq = 11774
current_ts = 282.353333
current_received_ts = 282.352722
current_seq = 11775
count = 40
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.337067/11774, current 282.353333/11775: elapsed=16260.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.353333
last_received_ts = 282.352722
last_seq = 11775
current_ts = 282.369568
current_received_ts = 282.368988
current_seq = 11776
count = 41
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.353333/11775, current 282.369568/11776: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.369568
last_received_ts = 282.368988
last_seq = 11776
current_ts = 282.385834
current_received_ts = 282.385223
current_seq = 11777
count = 42
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.369568/11776, current 282.385834/11777: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.385834
last_received_ts = 282.385223
last_seq = 11777
current_ts = 282.402100
current_received_ts = 282.401489
current_seq = 11778
count = 43
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.385834/11777, current 282.402100/11778: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.402100
last_received_ts = 282.401489
last_seq = 11778
current_ts = 282.418365
current_received_ts = 282.417755
current_seq = 11779
count = 44
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.402100/11778, current 282.418365/11779: elapsed=16261.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.418365
last_received_ts = 282.417755
last_seq = 11779
current_ts = 282.434631
current_received_ts = 282.434021
current_seq = 11780
count = 45
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.418365/11779, current 282.434631/11780: elapsed=16262.0us expected=16255.8us +- 81.3us, error 0.0%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.434631
last_received_ts = 282.434021
last_seq = 11780
current_ts = 282.450928
current_received_ts = 282.450348
current_seq = 11781
count = 46
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.434631/11780, current 282.450928/11781: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.450928
last_received_ts = 282.450348
last_seq = 11781
current_ts = 282.467255
current_received_ts = 282.466644
current_seq = 11782
count = 47
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.450928/11781, current 282.467255/11782: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.467255
last_received_ts = 282.466644
last_seq = 11782
current_ts = 282.483551
current_received_ts = 282.483093
current_seq = 11783
count = 48
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.467255/11782, current 282.483551/11783: elapsed=16306.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.483551
last_received_ts = 282.483093
last_seq = 11783
current_ts = 282.499847
current_received_ts = 282.499451
current_seq = 11784
count = 49
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.483551/11783, current 282.499847/11784: elapsed=16308.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.499847
last_received_ts = 282.499451
last_seq = 11784
current_ts = 282.516174
current_received_ts = 282.515625
current_seq = 11785
count = 50
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.499847/11784, current 282.516174/11785: elapsed=16318.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.516174
last_received_ts = 282.515625
last_seq = 11785
current_ts = 282.532501
current_received_ts = 282.531891
current_seq = 11786
count = 51
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.516174/11785, current 282.532501/11786: elapsed=16308.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.532501
last_received_ts = 282.531891
last_seq = 11786
current_ts = 282.548798
current_received_ts = 282.548187
current_seq = 11787
count = 52
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.532501/11786, current 282.548798/11787: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.548798
last_received_ts = 282.548187
last_seq = 11787
current_ts = 282.565094
current_received_ts = 282.564484
current_seq = 11788
count = 53
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.548798/11787, current 282.565094/11788: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.565094
last_received_ts = 282.564484
last_seq = 11788
current_ts = 282.581421
current_received_ts = 282.580811
current_seq = 11789
count = 54
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.565094/11788, current 282.581421/11789: elapsed=16317.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.581421
last_received_ts = 282.580811
last_seq = 11789
current_ts = 282.597748
current_received_ts = 282.597137
current_seq = 11790
count = 55
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.581421/11789, current 282.597748/11790: elapsed=16309.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.597748
last_received_ts = 282.597137
last_seq = 11790
current_ts = 282.614044
current_received_ts = 282.613434
current_seq = 11791
count = 56
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.597748/11790, current 282.614044/11791: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.614044
last_received_ts = 282.613434
last_seq = 11791
current_ts = 282.630371
current_received_ts = 282.629761
current_seq = 11792
count = 57
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.614044/11791, current 282.630371/11792: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.630371
last_received_ts = 282.629761
last_seq = 11792
current_ts = 282.646667
current_received_ts = 282.646057
current_seq = 11793
count = 58
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.630371/11792, current 282.646667/11793: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.646667
last_received_ts = 282.646057
last_seq = 11793
current_ts = 282.662964
current_received_ts = 282.662354
current_seq = 11794
count = 59
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.646667/11793, current 282.662964/11794: elapsed=16309.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.662964
last_received_ts = 282.662354
last_seq = 11794
current_ts = 282.679291
current_received_ts = 282.678680
current_seq = 11795
count = 60
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.662964/11794, current 282.679291/11795: elapsed=16314.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.679291
last_received_ts = 282.678680
last_seq = 11795
current_ts = 282.695618
current_received_ts = 282.695007
current_seq = 11796
count = 61
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.679291/11795, current 282.695618/11796: elapsed=16316.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.695618
last_received_ts = 282.695007
last_seq = 11796
current_ts = 282.711914
current_received_ts = 282.711365
current_seq = 11797
count = 62
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.695618/11796, current 282.711914/11797: elapsed=16303.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.711914
last_received_ts = 282.711365
last_seq = 11797
current_ts = 282.728210
current_received_ts = 282.727661
current_seq = 11798
count = 63
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.711914/11797, current 282.728210/11798: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.728210
last_received_ts = 282.727661
last_seq = 11798
current_ts = 282.744537
current_received_ts = 282.743988
current_seq = 11799
count = 64
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.728210/11798, current 282.744537/11799: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.744537
last_received_ts = 282.743988
last_seq = 11799
current_ts = 282.760834
current_received_ts = 282.760284
current_seq = 11800
count = 65
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.744537/11799, current 282.760834/11800: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.760834
last_received_ts = 282.760284
last_seq = 11800
current_ts = 282.777161
current_received_ts = 282.776611
current_seq = 11801
count = 66
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.760834/11800, current 282.777161/11801: elapsed=16318.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.777161
last_received_ts = 282.776611
last_seq = 11801
current_ts = 282.793457
current_received_ts = 282.792908
current_seq = 11802
count = 67
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.777161/11801, current 282.793457/11802: elapsed=16304.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.793457
last_received_ts = 282.792908
last_seq = 11802
current_ts = 282.809784
current_received_ts = 282.809235
current_seq = 11803
count = 68
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.793457/11802, current 282.809784/11803: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.809784
last_received_ts = 282.809235
last_seq = 11803
current_ts = 282.826080
current_received_ts = 282.825531
current_seq = 11804
count = 69
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.809784/11803, current 282.826080/11804: elapsed=16316.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.826080
last_received_ts = 282.825531
last_seq = 11804
current_ts = 282.842407
current_received_ts = 282.841858
current_seq = 11805
count = 70
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.826080/11804, current 282.842407/11805: elapsed=16306.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.842407
last_received_ts = 282.841858
last_seq = 11805
current_ts = 282.858704
current_received_ts = 282.858154
current_seq = 11806
count = 71
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.842407/11805, current 282.858704/11806: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.858704
last_received_ts = 282.858154
last_seq = 11806
current_ts = 282.875031
current_received_ts = 282.874481
current_seq = 11807
count = 72
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.858704/11806, current 282.875031/11807: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.875031
last_received_ts = 282.874481
last_seq = 11807
current_ts = 282.891327
current_received_ts = 282.890778
current_seq = 11808
count = 73
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.875031/11807, current 282.891327/11808: elapsed=16309.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.891327
last_received_ts = 282.890778
last_seq = 11808
current_ts = 282.907654
current_received_ts = 282.907104
current_seq = 11809
count = 74
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.891327/11808, current 282.907654/11809: elapsed=16324.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.907654
last_received_ts = 282.907104
last_seq = 11809
current_ts = 282.923950
current_received_ts = 282.923401
current_seq = 11810
count = 75
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.907654/11809, current 282.923950/11810: elapsed=16305.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.923950
last_received_ts = 282.923401
last_seq = 11810
current_ts = 282.940277
current_received_ts = 282.939728
current_seq = 11811
count = 76
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.923950/11810, current 282.940277/11811: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.940277
last_received_ts = 282.939728
last_seq = 11811
current_ts = 282.956573
current_received_ts = 282.956055
current_seq = 11812
count = 77
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.940277/11811, current 282.956573/11812: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.956573
last_received_ts = 282.956055
last_seq = 11812
current_ts = 282.972900
current_received_ts = 282.972351
current_seq = 11813
count = 78
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.956573/11812, current 282.972900/11813: elapsed=16314.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.972900
last_received_ts = 282.972351
last_seq = 11813
current_ts = 282.989197
current_received_ts = 282.988678
current_seq = 11814
count = 79
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.972900/11813, current 282.989197/11814: elapsed=16315.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 282.989197
last_received_ts = 282.988678
last_seq = 11814
current_ts = 283.005524
current_received_ts = 283.004974
current_seq = 11815
count = 80
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 282.989197/11814, current 283.005524/11815: elapsed=16303.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.005524
last_received_ts = 283.004974
last_seq = 11815
current_ts = 283.021820
current_received_ts = 283.021240
current_seq = 11816
count = 81
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.005524/11815, current 283.021820/11816: elapsed=16320.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.021820
last_received_ts = 283.021240
last_seq = 11816
current_ts = 283.038147
current_received_ts = 283.037598
current_seq = 11817
count = 82
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.021820/11816, current 283.038147/11817: elapsed=16304.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.038147
last_received_ts = 283.037598
last_seq = 11817
current_ts = 283.054443
current_received_ts = 283.053894
current_seq = 11818
count = 83
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.038147/11817, current 283.054443/11818: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.054443
last_received_ts = 283.053894
last_seq = 11818
current_ts = 283.070770
current_received_ts = 283.070190
current_seq = 11819
count = 84
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.054443/11818, current 283.070770/11819: elapsed=16319.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.070770
last_received_ts = 283.070190
last_seq = 11819
current_ts = 283.087067
current_received_ts = 283.086548
current_seq = 11820
count = 85
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.070770/11819, current 283.087067/11820: elapsed=16298.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.087067
last_received_ts = 283.086548
last_seq = 11820
current_ts = 283.103363
current_received_ts = 283.102844
current_seq = 11821
count = 86
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.087067/11820, current 283.103363/11821: elapsed=16313.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.103363
last_received_ts = 283.102844
last_seq = 11821
current_ts = 283.119690
current_received_ts = 283.119080
current_seq = 11822
count = 87
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.103363/11821, current 283.119690/11822: elapsed=16314.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.119690
last_received_ts = 283.119080
last_seq = 11822
current_ts = 283.135986
current_received_ts = 283.135376
current_seq = 11823
count = 88
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.119690/11822, current 283.135986/11823: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.135986
last_received_ts = 283.135376
last_seq = 11823
current_ts = 283.152313
current_received_ts = 283.151703
current_seq = 11824
count = 89
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.135986/11823, current 283.152313/11824: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.152313
last_received_ts = 283.151703
last_seq = 11824
current_ts = 283.168610
current_received_ts = 283.168030
current_seq = 11825
count = 90
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.152313/11824, current 283.168610/11825: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.168610
last_received_ts = 283.168030
last_seq = 11825
current_ts = 283.184937
current_received_ts = 283.184326
current_seq = 11826
count = 91
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.168610/11825, current 283.184937/11826: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.184937
last_received_ts = 283.184326
last_seq = 11826
current_ts = 283.201233
current_received_ts = 283.200623
current_seq = 11827
count = 92
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.184937/11826, current 283.201233/11827: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.201233
last_received_ts = 283.200623
last_seq = 11827
current_ts = 283.217560
current_received_ts = 283.216949
current_seq = 11828
count = 93
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.201233/11827, current 283.217560/11828: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.217560
last_received_ts = 283.216949
last_seq = 11828
current_ts = 283.233856
current_received_ts = 283.233246
current_seq = 11829
count = 94
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.217560/11828, current 283.233856/11829: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.233856
last_received_ts = 283.233246
last_seq = 11829
current_ts = 283.250183
current_received_ts = 283.249573
current_seq = 11830
count = 95
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.233856/11829, current 283.250183/11830: elapsed=16313.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.250183
last_received_ts = 283.249573
last_seq = 11830
current_ts = 283.266479
current_received_ts = 283.265869
current_seq = 11831
count = 96
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.250183/11830, current 283.266479/11831: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.266479
last_received_ts = 283.265869
last_seq = 11831
current_ts = 283.282806
current_received_ts = 283.282196
current_seq = 11832
count = 97
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.266479/11831, current 283.282806/11832: elapsed=16314.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.282806
last_received_ts = 283.282196
last_seq = 11832
current_ts = 283.299103
current_received_ts = 283.298492
current_seq = 11833
count = 98
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.282806/11832, current 283.299103/11833: elapsed=16309.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.299103
last_received_ts = 283.298492
last_seq = 11833
current_ts = 283.315430
current_received_ts = 283.314819
current_seq = 11834
count = 99
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.299103/11833, current 283.315430/11834: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.315430
last_received_ts = 283.314819
last_seq = 11834
current_ts = 283.331726
current_received_ts = 283.331238
current_seq = 11835
count = 100
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.315430/11834, current 283.331726/11835: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.331726
last_received_ts = 283.331238
last_seq = 11835
current_ts = 283.348053
current_received_ts = 283.347534
current_seq = 11836
count = 101
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.331726/11835, current 283.348053/11836: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.348053
last_received_ts = 283.347534
last_seq = 11836
current_ts = 283.364349
current_received_ts = 283.363739
current_seq = 11837
count = 102
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.348053/11836, current 283.364349/11837: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.364349
last_received_ts = 283.363739
last_seq = 11837
current_ts = 283.380676
current_received_ts = 283.380066
current_seq = 11838
count = 103
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.364349/11837, current 283.380676/11838: elapsed=16311.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.380676
last_received_ts = 283.380066
last_seq = 11838
current_ts = 283.396973
current_received_ts = 283.396362
current_seq = 11839
count = 104
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.380676/11838, current 283.396973/11839: elapsed=16316.0us expected=16255.8us +- 81.3us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.396973
last_received_ts = 283.396362
last_seq = 11839
current_ts = 283.413300
current_received_ts = 283.412689
current_seq = 11840
count = 105
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.396973/11839, current 283.413300/11840: elapsed=16312.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.413300
last_received_ts = 283.412689
last_seq = 11840
current_ts = 283.429596
current_received_ts = 283.428986
current_seq = 11841
count = 106
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.413300/11840, current 283.429596/11841: elapsed=16310.0us expected=16255.8us +- 81.3us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.429596
last_received_ts = 283.428986
last_seq = 11841
current_ts = 283.445953
current_received_ts = 283.445343
current_seq = 11842
count = 107
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.429596/11841, current 283.445953/11842: elapsed=16334.0us expected=16255.8us +- 81.3us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 283.445953
last_received_ts = 283.445343
last_seq = 11842
current_ts = 283.462280
current_received_ts = 283.461670
current_seq = 11843
count = 108
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 283.445953/11842, current 283.462280/11843: elapsed=16351.0us expected=16255.8us +- 81.3us, error 0.6%
(kms_flip:7604) DEBUG: inconsistent flip ts/seq: last 283.445953/11842, current 283.462280/11843: elapsed=16351.0us expected=16255.8us
(kms_flip:7604) DEBUG: expected 0, counted 108, encoder type 2
(kms_flip:7604) DEBUG: dropped frames, expected 0, counted 108, encoder type 2
(kms_flip:7604) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7604) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7604) igt_core-INFO: Stack trace:
(kms_flip:7604) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7604) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7604) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7604) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7604) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7604) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7604) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7604) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (7.385s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:7604) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7604) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7604) DEBUG: flip ts/seq: last 291.707794/12329, current 291.724365/12330: elapsed=16563.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.724365
last_received_ts = 291.723816
last_seq = 12330
current_ts = 291.740906
current_received_ts = 291.740387
current_seq = 12331
count = 169
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.724365/12330, current 291.740906/12331: elapsed=16547.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.740906
last_received_ts = 291.740387
last_seq = 12331
current_ts = 291.757477
current_received_ts = 291.756927
current_seq = 12332
count = 170
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.740906/12331, current 291.757477/12332: elapsed=16563.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.757477
last_received_ts = 291.756927
last_seq = 12332
current_ts = 291.774048
current_received_ts = 291.773468
current_seq = 12333
count = 171
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.757477/12332, current 291.774048/12333: elapsed=16553.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.774048
last_received_ts = 291.773468
last_seq = 12333
current_ts = 291.790588
current_received_ts = 291.789978
current_seq = 12334
count = 172
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.774048/12333, current 291.790588/12334: elapsed=16551.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.790588
last_received_ts = 291.789978
last_seq = 12334
current_ts = 291.807129
current_received_ts = 291.806580
current_seq = 12335
count = 173
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.790588/12334, current 291.807129/12335: elapsed=16548.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.807129
last_received_ts = 291.806580
last_seq = 12335
current_ts = 291.823700
current_received_ts = 291.823151
current_seq = 12336
count = 174
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.807129/12335, current 291.823700/12336: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.823700
last_received_ts = 291.823151
last_seq = 12336
current_ts = 291.840240
current_received_ts = 291.839722
current_seq = 12337
count = 175
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.823700/12336, current 291.840240/12337: elapsed=16545.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.840240
last_received_ts = 291.839722
last_seq = 12337
current_ts = 291.856812
current_received_ts = 291.856262
current_seq = 12338
count = 176
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.840240/12337, current 291.856812/12338: elapsed=16558.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.856812
last_received_ts = 291.856262
last_seq = 12338
current_ts = 291.873352
current_received_ts = 291.872803
current_seq = 12339
count = 177
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.856812/12338, current 291.873352/12339: elapsed=16562.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.873352
last_received_ts = 291.872803
last_seq = 12339
current_ts = 291.889923
current_received_ts = 291.889374
current_seq = 12340
count = 178
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.873352/12339, current 291.889923/12340: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.889923
last_received_ts = 291.889374
last_seq = 12340
current_ts = 291.906464
current_received_ts = 291.905914
current_seq = 12341
count = 179
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.889923/12340, current 291.906464/12341: elapsed=16552.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.906464
last_received_ts = 291.905914
last_seq = 12341
current_ts = 291.923035
current_received_ts = 291.922455
current_seq = 12342
count = 180
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.906464/12341, current 291.923035/12342: elapsed=16556.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.923035
last_received_ts = 291.922455
last_seq = 12342
current_ts = 291.939575
current_received_ts = 291.939056
current_seq = 12343
count = 181
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.923035/12342, current 291.939575/12343: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.939575
last_received_ts = 291.939056
last_seq = 12343
current_ts = 291.956146
current_received_ts = 291.955597
current_seq = 12344
count = 182
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.939575/12343, current 291.956146/12344: elapsed=16553.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.956146
last_received_ts = 291.955597
last_seq = 12344
current_ts = 291.972687
current_received_ts = 291.972137
current_seq = 12345
count = 183
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.956146/12344, current 291.972687/12345: elapsed=16552.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.972687
last_received_ts = 291.972137
last_seq = 12345
current_ts = 291.989258
current_received_ts = 291.988739
current_seq = 12346
count = 184
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.972687/12345, current 291.989258/12346: elapsed=16561.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 291.989258
last_received_ts = 291.988739
last_seq = 12346
current_ts = 292.005798
current_received_ts = 292.005310
current_seq = 12347
count = 185
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 291.989258/12346, current 292.005798/12347: elapsed=16549.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.005798
last_received_ts = 292.005310
last_seq = 12347
current_ts = 292.022339
current_received_ts = 292.021942
current_seq = 12348
count = 186
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.005798/12347, current 292.022339/12348: elapsed=16552.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.022339
last_received_ts = 292.021942
last_seq = 12348
current_ts = 292.038910
current_received_ts = 292.038300
current_seq = 12349
count = 187
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.022339/12348, current 292.038910/12349: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.038910
last_received_ts = 292.038300
last_seq = 12349
current_ts = 292.055450
current_received_ts = 292.054840
current_seq = 12350
count = 188
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.038910/12349, current 292.055450/12350: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.055450
last_received_ts = 292.054840
last_seq = 12350
current_ts = 292.072021
current_received_ts = 292.071411
current_seq = 12351
count = 189
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.055450/12350, current 292.072021/12351: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.072021
last_received_ts = 292.071411
last_seq = 12351
current_ts = 292.088562
current_received_ts = 292.087982
current_seq = 12352
count = 190
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.072021/12351, current 292.088562/12352: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.088562
last_received_ts = 292.087982
last_seq = 12352
current_ts = 292.105133
current_received_ts = 292.104523
current_seq = 12353
count = 191
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.088562/12352, current 292.105133/12353: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.105133
last_received_ts = 292.104523
last_seq = 12353
current_ts = 292.121674
current_received_ts = 292.121063
current_seq = 12354
count = 192
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.105133/12353, current 292.121674/12354: elapsed=16556.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.121674
last_received_ts = 292.121063
last_seq = 12354
current_ts = 292.138245
current_received_ts = 292.137634
current_seq = 12355
count = 193
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.121674/12354, current 292.138245/12355: elapsed=16553.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.138245
last_received_ts = 292.137634
last_seq = 12355
current_ts = 292.154785
current_received_ts = 292.154175
current_seq = 12356
count = 194
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.138245/12355, current 292.154785/12356: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.154785
last_received_ts = 292.154175
last_seq = 12356
current_ts = 292.171326
current_received_ts = 292.170746
current_seq = 12357
count = 195
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.154785/12356, current 292.171326/12357: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.171326
last_received_ts = 292.170746
last_seq = 12357
current_ts = 292.187897
current_received_ts = 292.187317
current_seq = 12358
count = 196
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.171326/12357, current 292.187897/12358: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.187897
last_received_ts = 292.187317
last_seq = 12358
current_ts = 292.204437
current_received_ts = 292.203857
current_seq = 12359
count = 197
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.187897/12358, current 292.204437/12359: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.204437
last_received_ts = 292.203857
last_seq = 12359
current_ts = 292.221008
current_received_ts = 292.220428
current_seq = 12360
count = 198
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.204437/12359, current 292.221008/12360: elapsed=16556.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.221008
last_received_ts = 292.220428
last_seq = 12360
current_ts = 292.237549
current_received_ts = 292.236969
current_seq = 12361
count = 199
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.221008/12360, current 292.237549/12361: elapsed=16553.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.237549
last_received_ts = 292.236969
last_seq = 12361
current_ts = 292.254120
current_received_ts = 292.253510
current_seq = 12362
count = 200
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.237549/12361, current 292.254120/12362: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.254120
last_received_ts = 292.253510
last_seq = 12362
current_ts = 292.270660
current_received_ts = 292.270081
current_seq = 12363
count = 201
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.254120/12362, current 292.270660/12363: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.270660
last_received_ts = 292.270081
last_seq = 12363
current_ts = 292.287231
current_received_ts = 292.286621
current_seq = 12364
count = 202
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.270660/12363, current 292.287231/12364: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.287231
last_received_ts = 292.286621
last_seq = 12364
current_ts = 292.303772
current_received_ts = 292.303162
current_seq = 12365
count = 203
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.287231/12364, current 292.303772/12365: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.303772
last_received_ts = 292.303162
last_seq = 12365
current_ts = 292.320343
current_received_ts = 292.319733
current_seq = 12366
count = 204
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.303772/12365, current 292.320343/12366: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.320343
last_received_ts = 292.319733
last_seq = 12366
current_ts = 292.336884
current_received_ts = 292.336304
current_seq = 12367
count = 205
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.320343/12366, current 292.336884/12367: elapsed=16553.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.336884
last_received_ts = 292.336304
last_seq = 12367
current_ts = 292.353455
current_received_ts = 292.352844
current_seq = 12368
count = 206
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.336884/12367, current 292.353455/12368: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.353455
last_received_ts = 292.352844
last_seq = 12368
current_ts = 292.369995
current_received_ts = 292.369385
current_seq = 12369
count = 207
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.353455/12368, current 292.369995/12369: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.369995
last_received_ts = 292.369385
last_seq = 12369
current_ts = 292.386536
current_received_ts = 292.385956
current_seq = 12370
count = 208
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.369995/12369, current 292.386536/12370: elapsed=16554.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.386536
last_received_ts = 292.385956
last_seq = 12370
current_ts = 292.403107
current_received_ts = 292.402496
current_seq = 12371
count = 209
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.386536/12370, current 292.403107/12371: elapsed=16555.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.403107
last_received_ts = 292.402496
last_seq = 12371
current_ts = 292.419678
current_received_ts = 292.419067
current_seq = 12372
count = 210
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.403107/12371, current 292.419678/12372: elapsed=16558.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.419678
last_received_ts = 292.419067
last_seq = 12372
current_ts = 292.436218
current_received_ts = 292.435608
current_seq = 12373
count = 211
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.419678/12372, current 292.436218/12373: elapsed=16551.0us expected=16503.1us +- 82.5us, error 0.3%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.436218
last_received_ts = 292.435608
last_seq = 12373
current_ts = 292.452789
current_received_ts = 292.452179
current_seq = 12374
count = 212
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.436218/12373, current 292.452789/12374: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.452789
last_received_ts = 292.452179
last_seq = 12374
current_ts = 292.469360
current_received_ts = 292.468750
current_seq = 12375
count = 213
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.452789/12374, current 292.469360/12375: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.469360
last_received_ts = 292.468750
last_seq = 12375
current_ts = 292.485931
current_received_ts = 292.485321
current_seq = 12376
count = 214
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.469360/12375, current 292.485931/12376: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.485931
last_received_ts = 292.485321
last_seq = 12376
current_ts = 292.502472
current_received_ts = 292.501892
current_seq = 12377
count = 215
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.485931/12376, current 292.502472/12377: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.502472
last_received_ts = 292.501892
last_seq = 12377
current_ts = 292.519043
current_received_ts = 292.518463
current_seq = 12378
count = 216
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.502472/12377, current 292.519043/12378: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.519043
last_received_ts = 292.518463
last_seq = 12378
current_ts = 292.535614
current_received_ts = 292.535034
current_seq = 12379
count = 217
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.519043/12378, current 292.535614/12379: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.535614
last_received_ts = 292.535034
last_seq = 12379
current_ts = 292.552185
current_received_ts = 292.551575
current_seq = 12380
count = 218
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.535614/12379, current 292.552185/12380: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.552185
last_received_ts = 292.551575
last_seq = 12380
current_ts = 292.568756
current_received_ts = 292.568146
current_seq = 12381
count = 219
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.552185/12380, current 292.568756/12381: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.568756
last_received_ts = 292.568146
last_seq = 12381
current_ts = 292.585327
current_received_ts = 292.584717
current_seq = 12382
count = 220
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.568756/12381, current 292.585327/12382: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.585327
last_received_ts = 292.584717
last_seq = 12382
current_ts = 292.601898
current_received_ts = 292.601288
current_seq = 12383
count = 221
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.585327/12382, current 292.601898/12383: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.601898
last_received_ts = 292.601288
last_seq = 12383
current_ts = 292.618469
current_received_ts = 292.617859
current_seq = 12384
count = 222
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.601898/12383, current 292.618469/12384: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.618469
last_received_ts = 292.617859
last_seq = 12384
current_ts = 292.635040
current_received_ts = 292.634430
current_seq = 12385
count = 223
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.618469/12384, current 292.635040/12385: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.635040
last_received_ts = 292.634430
last_seq = 12385
current_ts = 292.651581
current_received_ts = 292.651001
current_seq = 12386
count = 224
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.635040/12385, current 292.651581/12386: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.651581
last_received_ts = 292.651001
last_seq = 12386
current_ts = 292.668152
current_received_ts = 292.667572
current_seq = 12387
count = 225
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.651581/12386, current 292.668152/12387: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.668152
last_received_ts = 292.667572
last_seq = 12387
current_ts = 292.684723
current_received_ts = 292.684143
current_seq = 12388
count = 226
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.668152/12387, current 292.684723/12388: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.684723
last_received_ts = 292.684143
last_seq = 12388
current_ts = 292.701294
current_received_ts = 292.700684
current_seq = 12389
count = 227
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.684723/12388, current 292.701294/12389: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.701294
last_received_ts = 292.700684
last_seq = 12389
current_ts = 292.717865
current_received_ts = 292.717255
current_seq = 12390
count = 228
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.701294/12389, current 292.717865/12390: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.717865
last_received_ts = 292.717255
last_seq = 12390
current_ts = 292.734436
current_received_ts = 292.733826
current_seq = 12391
count = 229
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.717865/12390, current 292.734436/12391: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.734436
last_received_ts = 292.733826
last_seq = 12391
current_ts = 292.751007
current_received_ts = 292.750397
current_seq = 12392
count = 230
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.734436/12391, current 292.751007/12392: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.751007
last_received_ts = 292.750397
last_seq = 12392
current_ts = 292.767578
current_received_ts = 292.766968
current_seq = 12393
count = 231
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.751007/12392, current 292.767578/12393: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.767578
last_received_ts = 292.766968
last_seq = 12393
current_ts = 292.784149
current_received_ts = 292.783539
current_seq = 12394
count = 232
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.767578/12393, current 292.784149/12394: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.784149
last_received_ts = 292.783539
last_seq = 12394
current_ts = 292.800690
current_received_ts = 292.800110
current_seq = 12395
count = 233
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.784149/12394, current 292.800690/12395: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.800690
last_received_ts = 292.800110
last_seq = 12395
current_ts = 292.817261
current_received_ts = 292.816681
current_seq = 12396
count = 234
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.800690/12395, current 292.817261/12396: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.817261
last_received_ts = 292.816681
last_seq = 12396
current_ts = 292.833832
current_received_ts = 292.833221
current_seq = 12397
count = 235
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.817261/12396, current 292.833832/12397: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.833832
last_received_ts = 292.833221
last_seq = 12397
current_ts = 292.850403
current_received_ts = 292.849792
current_seq = 12398
count = 236
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.833832/12397, current 292.850403/12398: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.850403
last_received_ts = 292.849792
last_seq = 12398
current_ts = 292.866974
current_received_ts = 292.866364
current_seq = 12399
count = 237
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.850403/12398, current 292.866974/12399: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.866974
last_received_ts = 292.866364
last_seq = 12399
current_ts = 292.883545
current_received_ts = 292.882996
current_seq = 12400
count = 238
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.866974/12399, current 292.883545/12400: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.883545
last_received_ts = 292.882996
last_seq = 12400
current_ts = 292.900116
current_received_ts = 292.899658
current_seq = 12401
count = 239
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.883545/12400, current 292.900116/12401: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.900116
last_received_ts = 292.899658
last_seq = 12401
current_ts = 292.916687
current_received_ts = 292.916199
current_seq = 12402
count = 240
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.900116/12401, current 292.916687/12402: elapsed=16572.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.916687
last_received_ts = 292.916199
last_seq = 12402
current_ts = 292.933258
current_received_ts = 292.932739
current_seq = 12403
count = 241
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.916687/12402, current 292.933258/12403: elapsed=16564.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.933258
last_received_ts = 292.932739
last_seq = 12403
current_ts = 292.949829
current_received_ts = 292.949249
current_seq = 12404
count = 242
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.933258/12403, current 292.949829/12404: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.949829
last_received_ts = 292.949249
last_seq = 12404
current_ts = 292.966370
current_received_ts = 292.965790
current_seq = 12405
count = 243
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.949829/12404, current 292.966370/12405: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.966370
last_received_ts = 292.965790
last_seq = 12405
current_ts = 292.982941
current_received_ts = 292.982361
current_seq = 12406
count = 244
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.966370/12405, current 292.982941/12406: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.982941
last_received_ts = 292.982361
last_seq = 12406
current_ts = 292.999512
current_received_ts = 292.998901
current_seq = 12407
count = 245
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.982941/12406, current 292.999512/12407: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 292.999512
last_received_ts = 292.998901
last_seq = 12407
current_ts = 293.016083
current_received_ts = 293.015503
current_seq = 12408
count = 246
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 292.999512/12407, current 293.016083/12408: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.016083
last_received_ts = 293.015503
last_seq = 12408
current_ts = 293.032654
current_received_ts = 293.032135
current_seq = 12409
count = 247
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.016083/12408, current 293.032654/12409: elapsed=16570.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.032654
last_received_ts = 293.032135
last_seq = 12409
current_ts = 293.049225
current_received_ts = 293.048615
current_seq = 12410
count = 248
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.032654/12409, current 293.049225/12410: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.049225
last_received_ts = 293.048615
last_seq = 12410
current_ts = 293.065796
current_received_ts = 293.065186
current_seq = 12411
count = 249
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.049225/12410, current 293.065796/12411: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.065796
last_received_ts = 293.065186
last_seq = 12411
current_ts = 293.082367
current_received_ts = 293.081757
current_seq = 12412
count = 250
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.065796/12411, current 293.082367/12412: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.082367
last_received_ts = 293.081757
last_seq = 12412
current_ts = 293.098938
current_received_ts = 293.098328
current_seq = 12413
count = 251
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.082367/12412, current 293.098938/12413: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.098938
last_received_ts = 293.098328
last_seq = 12413
current_ts = 293.115479
current_received_ts = 293.115112
current_seq = 12414
count = 252
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.098938/12413, current 293.115479/12414: elapsed=16570.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.115479
last_received_ts = 293.115112
last_seq = 12414
current_ts = 293.132050
current_received_ts = 293.131592
current_seq = 12415
count = 253
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.115479/12414, current 293.132050/12415: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.132050
last_received_ts = 293.131592
last_seq = 12415
current_ts = 293.148621
current_received_ts = 293.148163
current_seq = 12416
count = 254
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.132050/12415, current 293.148621/12416: elapsed=16564.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.148621
last_received_ts = 293.148163
last_seq = 12416
current_ts = 293.165192
current_received_ts = 293.164703
current_seq = 12417
count = 255
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.148621/12416, current 293.165192/12417: elapsed=16570.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.165192
last_received_ts = 293.164703
last_seq = 12417
current_ts = 293.181763
current_received_ts = 293.181152
current_seq = 12418
count = 256
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.165192/12417, current 293.181763/12418: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.181763
last_received_ts = 293.181152
last_seq = 12418
current_ts = 293.198334
current_received_ts = 293.197723
current_seq = 12419
count = 257
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.181763/12418, current 293.198334/12419: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.198334
last_received_ts = 293.197723
last_seq = 12419
current_ts = 293.214905
current_received_ts = 293.214294
current_seq = 12420
count = 258
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.198334/12419, current 293.214905/12420: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.214905
last_received_ts = 293.214294
last_seq = 12420
current_ts = 293.231476
current_received_ts = 293.230896
current_seq = 12421
count = 259
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.214905/12420, current 293.231476/12421: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.231476
last_received_ts = 293.230896
last_seq = 12421
current_ts = 293.248047
current_received_ts = 293.247437
current_seq = 12422
count = 260
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.231476/12421, current 293.248047/12422: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.248047
last_received_ts = 293.247437
last_seq = 12422
current_ts = 293.264587
current_received_ts = 293.264038
current_seq = 12423
count = 261
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.248047/12422, current 293.264587/12423: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.264587
last_received_ts = 293.264038
last_seq = 12423
current_ts = 293.281158
current_received_ts = 293.280579
current_seq = 12424
count = 262
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.264587/12423, current 293.281158/12424: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.281158
last_received_ts = 293.280579
last_seq = 12424
current_ts = 293.297729
current_received_ts = 293.297150
current_seq = 12425
count = 263
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.281158/12424, current 293.297729/12425: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.297729
last_received_ts = 293.297150
last_seq = 12425
current_ts = 293.314301
current_received_ts = 293.313690
current_seq = 12426
count = 264
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.297729/12425, current 293.314301/12426: elapsed=16566.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.314301
last_received_ts = 293.313690
last_seq = 12426
current_ts = 293.330872
current_received_ts = 293.330261
current_seq = 12427
count = 265
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.314301/12426, current 293.330872/12427: elapsed=16569.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.330872
last_received_ts = 293.330261
last_seq = 12427
current_ts = 293.347443
current_received_ts = 293.346832
current_seq = 12428
count = 266
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.330872/12427, current 293.347443/12428: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.347443
last_received_ts = 293.346832
last_seq = 12428
current_ts = 293.364014
current_received_ts = 293.363403
current_seq = 12429
count = 267
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.347443/12428, current 293.364014/12429: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.364014
last_received_ts = 293.363403
last_seq = 12429
current_ts = 293.380585
current_received_ts = 293.380157
current_seq = 12430
count = 268
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.364014/12429, current 293.380585/12430: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.380585
last_received_ts = 293.380157
last_seq = 12430
current_ts = 293.397156
current_received_ts = 293.396637
current_seq = 12431
count = 269
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.380585/12430, current 293.397156/12431: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.397156
last_received_ts = 293.396637
last_seq = 12431
current_ts = 293.413696
current_received_ts = 293.413177
current_seq = 12432
count = 270
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.397156/12431, current 293.413696/12432: elapsed=16567.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.413696
last_received_ts = 293.413177
last_seq = 12432
current_ts = 293.430267
current_received_ts = 293.429779
current_seq = 12433
count = 271
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.413696/12432, current 293.430267/12433: elapsed=16568.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.430267
last_received_ts = 293.429779
last_seq = 12433
current_ts = 293.446838
current_received_ts = 293.446289
current_seq = 12434
count = 272
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.430267/12433, current 293.446838/12434: elapsed=16575.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.446838
last_received_ts = 293.446289
last_seq = 12434
current_ts = 293.463440
current_received_ts = 293.462830
current_seq = 12435
count = 273
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.446838/12434, current 293.463440/12435: elapsed=16580.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.463440
last_received_ts = 293.462830
last_seq = 12435
current_ts = 293.480011
current_received_ts = 293.479401
current_seq = 12436
count = 274
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.463440/12435, current 293.480011/12436: elapsed=16578.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.480011
last_received_ts = 293.479401
last_seq = 12436
current_ts = 293.496582
current_received_ts = 293.496033
current_seq = 12437
count = 275
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.480011/12436, current 293.496582/12437: elapsed=16580.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.496582
last_received_ts = 293.496033
last_seq = 12437
current_ts = 293.513184
current_received_ts = 293.512665
current_seq = 12438
count = 276
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.496582/12437, current 293.513184/12438: elapsed=16579.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.513184
last_received_ts = 293.512665
last_seq = 12438
current_ts = 293.529755
current_received_ts = 293.529175
current_seq = 12439
count = 277
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.513184/12438, current 293.529755/12439: elapsed=16577.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.529755
last_received_ts = 293.529175
last_seq = 12439
current_ts = 293.546326
current_received_ts = 293.545746
current_seq = 12440
count = 278
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.529755/12439, current 293.546326/12440: elapsed=16581.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.546326
last_received_ts = 293.545746
last_seq = 12440
current_ts = 293.562897
current_received_ts = 293.562286
current_seq = 12441
count = 279
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.546326/12440, current 293.562897/12441: elapsed=16579.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.562897
last_received_ts = 293.562286
last_seq = 12441
current_ts = 293.579498
current_received_ts = 293.578888
current_seq = 12442
count = 280
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.562897/12441, current 293.579498/12442: elapsed=16579.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.579498
last_received_ts = 293.578888
last_seq = 12442
current_ts = 293.596069
current_received_ts = 293.595459
current_seq = 12443
count = 281
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.579498/12442, current 293.596069/12443: elapsed=16579.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.596069
last_received_ts = 293.595459
last_seq = 12443
current_ts = 293.612640
current_received_ts = 293.612091
current_seq = 12444
count = 282
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.596069/12443, current 293.612640/12444: elapsed=16580.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.612640
last_received_ts = 293.612091
last_seq = 12444
current_ts = 293.629211
current_received_ts = 293.628632
current_seq = 12445
count = 283
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.612640/12444, current 293.629211/12445: elapsed=16578.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.629211
last_received_ts = 293.628632
last_seq = 12445
current_ts = 293.645813
current_received_ts = 293.645264
current_seq = 12446
count = 284
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.629211/12445, current 293.645813/12446: elapsed=16583.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.645813
last_received_ts = 293.645264
last_seq = 12446
current_ts = 293.662384
current_received_ts = 293.661835
current_seq = 12447
count = 285
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.645813/12446, current 293.662384/12447: elapsed=16582.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.662384
last_received_ts = 293.661835
last_seq = 12447
current_ts = 293.678955
current_received_ts = 293.678406
current_seq = 12448
count = 286
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.662384/12447, current 293.678955/12448: elapsed=16571.0us expected=16503.1us +- 82.5us, error 0.4%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.678955
last_received_ts = 293.678406
last_seq = 12448
current_ts = 293.695526
current_received_ts = 293.695038
current_seq = 12449
count = 287
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.678955/12448, current 293.695526/12449: elapsed=16580.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: name = flip
last_ts = 293.695526
last_received_ts = 293.695038
last_seq = 12449
current_ts = 293.712128
current_received_ts = 293.711578
current_seq = 12450
count = 288
seq_step = 1
(kms_flip:7604) DEBUG: flip ts/seq: last 293.695526/12449, current 293.712128/12450: elapsed=16587.0us expected=16503.1us +- 82.5us, error 0.5%
(kms_flip:7604) DEBUG: inconsistent flip ts/seq: last 293.695526/12449, current 293.712128/12450: elapsed=16587.0us expected=16503.1us
(kms_flip:7604) DEBUG: expected 0, counted 288, encoder type 2
(kms_flip:7604) DEBUG: dropped frames, expected 0, counted 288, encoder type 2
(kms_flip:7604) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7604) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7604) igt_core-INFO: Stack trace:
(kms_flip:7604) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7604) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7604) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7604) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7604) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7604) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7604) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7604) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (9.757s)
Starting dynamic subtest: AD-DP2-HDMI-A3
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.686s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.675s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.646s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.639s)
Subtest 2x-plain-flip-ts-check: FAIL (39.832s)