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

shard-bmg-7

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

Using IGT_SRANDOM=1741122824 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 16294.6us +- 20.643us accuracy 0.38%
vblank interval differs from modeline! expected 16666.7us, measured 16295us +- 20.643us, difference 372.1us (18.0 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c: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 (6.975s)
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 16504.6us +- 8.277us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 16505us +- 8.277us, difference 162.0us (19.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c: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.018s)
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 16611.8us +- 1.515us accuracy 0.03%
vblank interval differs from modeline! expected 16666.7us, measured 16612us +- 1.515us, difference 54.9us (36.2 sigma)
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.688s)
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 16637.9us +- 3.500us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16638us +- 3.500us, difference 28.8us (8.2 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.692s)
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 16649.8us +- 3.728us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 16650us +- 3.728us, difference 16.9us (4.5 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.680s)
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 16677.6us +- 1.672us accuracy 0.03%
vblank interval differs from modeline! expected 16666.7us, measured 16678us +- 1.672us, difference 10.9us (6.5 sigma)
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.659s)
Subtest 2x-plain-flip-ts-check: FAIL (38.771s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:4847) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:4847) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:4847) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:4847) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198b98f80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198b98f80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198bde380, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198bde380, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198ba6b90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198ba6b90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198ba6b90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) intel_allocator_simple-DEBUG: <ial: 0x64c198ba6b90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:4847) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:4847) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:4847) DEBUG: No stale events found
(kms_flip:4847) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:4847) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:4847) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:4847) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:4847) INFO: Expected frametime: 16667us; measured 16294.6us +- 20.643us accuracy 0.38%
(kms_flip:4847) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16295us +- 20.643us, difference 372.1us (18.0 sigma)
(kms_flip:4847) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 215.597748
current_received_ts = 215.597183
current_seq = 8423
count = 0
seq_step = 1
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.597748
last_received_ts = 215.597183
last_seq = 8423
current_ts = 215.614059
current_received_ts = 215.613449
current_seq = 8424
count = 1
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.597748/8423, current 215.614059/8424: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.614059
last_received_ts = 215.613449
last_seq = 8424
current_ts = 215.630356
current_received_ts = 215.629745
current_seq = 8425
count = 2
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.614059/8424, current 215.630356/8425: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.630356
last_received_ts = 215.629745
last_seq = 8425
current_ts = 215.646667
current_received_ts = 215.646072
current_seq = 8426
count = 3
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.630356/8425, current 215.646667/8426: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.646667
last_received_ts = 215.646072
last_seq = 8426
current_ts = 215.662979
current_received_ts = 215.662354
current_seq = 8427
count = 4
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.646667/8426, current 215.662979/8427: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.662979
last_received_ts = 215.662354
last_seq = 8427
current_ts = 215.679276
current_received_ts = 215.678665
current_seq = 8428
count = 5
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.662979/8427, current 215.679276/8428: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.679276
last_received_ts = 215.678665
last_seq = 8428
current_ts = 215.695587
current_received_ts = 215.694962
current_seq = 8429
count = 6
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.679276/8428, current 215.695587/8429: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.695587
last_received_ts = 215.694962
last_seq = 8429
current_ts = 215.711884
current_received_ts = 215.711273
current_seq = 8430
count = 7
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.695587/8429, current 215.711884/8430: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.711884
last_received_ts = 215.711273
last_seq = 8430
current_ts = 215.728195
current_received_ts = 215.727585
current_seq = 8431
count = 8
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.711884/8430, current 215.728195/8431: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.728195
last_received_ts = 215.727585
last_seq = 8431
current_ts = 215.744492
current_received_ts = 215.743881
current_seq = 8432
count = 9
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.728195/8431, current 215.744492/8432: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.744492
last_received_ts = 215.743881
last_seq = 8432
current_ts = 215.760803
current_received_ts = 215.760193
current_seq = 8433
count = 10
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.744492/8432, current 215.760803/8433: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.760803
last_received_ts = 215.760193
last_seq = 8433
current_ts = 215.777100
current_received_ts = 215.776489
current_seq = 8434
count = 11
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.760803/8433, current 215.777100/8434: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.777100
last_received_ts = 215.776489
last_seq = 8434
current_ts = 215.793411
current_received_ts = 215.792801
current_seq = 8435
count = 12
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.777100/8434, current 215.793411/8435: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.793411
last_received_ts = 215.792801
last_seq = 8435
current_ts = 215.809708
current_received_ts = 215.809097
current_seq = 8436
count = 13
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.793411/8435, current 215.809708/8436: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.809708
last_received_ts = 215.809097
last_seq = 8436
current_ts = 215.826019
current_received_ts = 215.825409
current_seq = 8437
count = 14
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.809708/8436, current 215.826019/8437: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.826019
last_received_ts = 215.825409
last_seq = 8437
current_ts = 215.842331
current_received_ts = 215.841705
current_seq = 8438
count = 15
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.826019/8437, current 215.842331/8438: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.842331
last_received_ts = 215.841705
last_seq = 8438
current_ts = 215.858627
current_received_ts = 215.858032
current_seq = 8439
count = 16
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.842331/8438, current 215.858627/8439: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.858627
last_received_ts = 215.858032
last_seq = 8439
current_ts = 215.874939
current_received_ts = 215.874313
current_seq = 8440
count = 17
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.858627/8439, current 215.874939/8440: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.874939
last_received_ts = 215.874313
last_seq = 8440
current_ts = 215.891235
current_received_ts = 215.890625
current_seq = 8441
count = 18
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.874939/8440, current 215.891235/8441: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.891235
last_received_ts = 215.890625
last_seq = 8441
current_ts = 215.907547
current_received_ts = 215.906921
current_seq = 8442
count = 19
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.891235/8441, current 215.907547/8442: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.907547
last_received_ts = 215.906921
last_seq = 8442
current_ts = 215.923843
current_received_ts = 215.923233
current_seq = 8443
count = 20
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.907547/8442, current 215.923843/8443: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.923843
last_received_ts = 215.923233
last_seq = 8443
current_ts = 215.940155
current_received_ts = 215.939545
current_seq = 8444
count = 21
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.923843/8443, current 215.940155/8444: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.940155
last_received_ts = 215.939545
last_seq = 8444
current_ts = 215.956451
current_received_ts = 215.955902
current_seq = 8445
count = 22
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.940155/8444, current 215.956451/8445: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.956451
last_received_ts = 215.955902
last_seq = 8445
current_ts = 215.972763
current_received_ts = 215.972153
current_seq = 8446
count = 23
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.956451/8445, current 215.972763/8446: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.972763
last_received_ts = 215.972153
last_seq = 8446
current_ts = 215.989059
current_received_ts = 215.988449
current_seq = 8447
count = 24
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.972763/8446, current 215.989059/8447: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 215.989059
last_received_ts = 215.988449
last_seq = 8447
current_ts = 216.005371
current_received_ts = 216.004913
current_seq = 8448
count = 25
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 215.989059/8447, current 216.005371/8448: elapsed=16306.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.005371
last_received_ts = 216.004913
last_seq = 8448
current_ts = 216.021667
current_received_ts = 216.021103
current_seq = 8449
count = 26
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.005371/8448, current 216.021667/8449: elapsed=16301.0us expected=16294.6us +- 81.5us, error 0.0%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.021667
last_received_ts = 216.021103
last_seq = 8449
current_ts = 216.037979
current_received_ts = 216.037506
current_seq = 8450
count = 27
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.021667/8449, current 216.037979/8450: elapsed=16308.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.037979
last_received_ts = 216.037506
last_seq = 8450
current_ts = 216.054291
current_received_ts = 216.053711
current_seq = 8451
count = 28
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.037979/8450, current 216.054291/8451: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.054291
last_received_ts = 216.053711
last_seq = 8451
current_ts = 216.070587
current_received_ts = 216.070114
current_seq = 8452
count = 29
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.054291/8451, current 216.070587/8452: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.070587
last_received_ts = 216.070114
last_seq = 8452
current_ts = 216.086899
current_received_ts = 216.086319
current_seq = 8453
count = 30
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.070587/8452, current 216.086899/8453: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.086899
last_received_ts = 216.086319
last_seq = 8453
current_ts = 216.103195
current_received_ts = 216.102600
current_seq = 8454
count = 31
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.086899/8453, current 216.103195/8454: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.103195
last_received_ts = 216.102600
last_seq = 8454
current_ts = 216.119507
current_received_ts = 216.118896
current_seq = 8455
count = 32
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.103195/8454, current 216.119507/8455: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.119507
last_received_ts = 216.118896
last_seq = 8455
current_ts = 216.135803
current_received_ts = 216.135208
current_seq = 8456
count = 33
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.119507/8455, current 216.135803/8456: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.135803
last_received_ts = 216.135208
last_seq = 8456
current_ts = 216.152115
current_received_ts = 216.151505
current_seq = 8457
count = 34
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.135803/8456, current 216.152115/8457: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.152115
last_received_ts = 216.151505
last_seq = 8457
current_ts = 216.168427
current_received_ts = 216.167816
current_seq = 8458
count = 35
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.152115/8457, current 216.168427/8458: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.168427
last_received_ts = 216.167816
last_seq = 8458
current_ts = 216.184723
current_received_ts = 216.184113
current_seq = 8459
count = 36
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.168427/8458, current 216.184723/8459: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.184723
last_received_ts = 216.184113
last_seq = 8459
current_ts = 216.201035
current_received_ts = 216.200424
current_seq = 8460
count = 37
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.184723/8459, current 216.201035/8460: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.201035
last_received_ts = 216.200424
last_seq = 8460
current_ts = 216.217331
current_received_ts = 216.216721
current_seq = 8461
count = 38
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.201035/8460, current 216.217331/8461: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.217331
last_received_ts = 216.216721
last_seq = 8461
current_ts = 216.233643
current_received_ts = 216.233063
current_seq = 8462
count = 39
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.217331/8461, current 216.233643/8462: elapsed=16306.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.233643
last_received_ts = 216.233063
last_seq = 8462
current_ts = 216.249939
current_received_ts = 216.249329
current_seq = 8463
count = 40
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.233643/8462, current 216.249939/8463: elapsed=16303.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.249939
last_received_ts = 216.249329
last_seq = 8463
current_ts = 216.266251
current_received_ts = 216.265640
current_seq = 8464
count = 41
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.249939/8463, current 216.266251/8464: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.266251
last_received_ts = 216.265640
last_seq = 8464
current_ts = 216.282547
current_received_ts = 216.281937
current_seq = 8465
count = 42
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.266251/8464, current 216.282547/8465: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.282547
last_received_ts = 216.281937
last_seq = 8465
current_ts = 216.298859
current_received_ts = 216.298248
current_seq = 8466
count = 43
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.282547/8465, current 216.298859/8466: elapsed=16306.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.298859
last_received_ts = 216.298248
last_seq = 8466
current_ts = 216.315170
current_received_ts = 216.314545
current_seq = 8467
count = 44
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.298859/8466, current 216.315170/8467: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.315170
last_received_ts = 216.314545
last_seq = 8467
current_ts = 216.331467
current_received_ts = 216.330856
current_seq = 8468
count = 45
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.315170/8467, current 216.331467/8468: elapsed=16304.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.331467
last_received_ts = 216.330856
last_seq = 8468
current_ts = 216.347778
current_received_ts = 216.347153
current_seq = 8469
count = 46
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.331467/8468, current 216.347778/8469: elapsed=16305.0us expected=16294.6us +- 81.5us, error 0.1%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.347778
last_received_ts = 216.347153
last_seq = 8469
current_ts = 216.364090
current_received_ts = 216.363480
current_seq = 8470
count = 47
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.347778/8469, current 216.364090/8470: elapsed=16322.0us expected=16294.6us +- 81.5us, error 0.2%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.364090
last_received_ts = 216.363480
last_seq = 8470
current_ts = 216.380447
current_received_ts = 216.379837
current_seq = 8471
count = 48
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.364090/8470, current 216.380447/8471: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.380447
last_received_ts = 216.379837
last_seq = 8471
current_ts = 216.396790
current_received_ts = 216.396179
current_seq = 8472
count = 49
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.380447/8471, current 216.396790/8472: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.396790
last_received_ts = 216.396179
last_seq = 8472
current_ts = 216.413147
current_received_ts = 216.412521
current_seq = 8473
count = 50
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.396790/8472, current 216.413147/8473: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.413147
last_received_ts = 216.412521
last_seq = 8473
current_ts = 216.429489
current_received_ts = 216.428879
current_seq = 8474
count = 51
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.413147/8473, current 216.429489/8474: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.429489
last_received_ts = 216.428879
last_seq = 8474
current_ts = 216.445847
current_received_ts = 216.445221
current_seq = 8475
count = 52
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.429489/8474, current 216.445847/8475: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.445847
last_received_ts = 216.445221
last_seq = 8475
current_ts = 216.462189
current_received_ts = 216.461578
current_seq = 8476
count = 53
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.445847/8475, current 216.462189/8476: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.462189
last_received_ts = 216.461578
last_seq = 8476
current_ts = 216.478531
current_received_ts = 216.477921
current_seq = 8477
count = 54
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.462189/8476, current 216.478531/8477: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.478531
last_received_ts = 216.477921
last_seq = 8477
current_ts = 216.494888
current_received_ts = 216.494278
current_seq = 8478
count = 55
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.478531/8477, current 216.494888/8478: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.494888
last_received_ts = 216.494278
last_seq = 8478
current_ts = 216.511230
current_received_ts = 216.510620
current_seq = 8479
count = 56
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.494888/8478, current 216.511230/8479: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.511230
last_received_ts = 216.510620
last_seq = 8479
current_ts = 216.527588
current_received_ts = 216.526978
current_seq = 8480
count = 57
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.511230/8479, current 216.527588/8480: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.527588
last_received_ts = 216.526978
last_seq = 8480
current_ts = 216.543930
current_received_ts = 216.543320
current_seq = 8481
count = 58
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.527588/8480, current 216.543930/8481: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.543930
last_received_ts = 216.543320
last_seq = 8481
current_ts = 216.560287
current_received_ts = 216.559662
current_seq = 8482
count = 59
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.543930/8481, current 216.560287/8482: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.560287
last_received_ts = 216.559662
last_seq = 8482
current_ts = 216.576630
current_received_ts = 216.576035
current_seq = 8483
count = 60
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.560287/8482, current 216.576630/8483: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.576630
last_received_ts = 216.576035
last_seq = 8483
current_ts = 216.592987
current_received_ts = 216.592361
current_seq = 8484
count = 61
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.576630/8483, current 216.592987/8484: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.592987
last_received_ts = 216.592361
last_seq = 8484
current_ts = 216.609329
current_received_ts = 216.608719
current_seq = 8485
count = 62
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.592987/8484, current 216.609329/8485: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.609329
last_received_ts = 216.608719
last_seq = 8485
current_ts = 216.625687
current_received_ts = 216.625061
current_seq = 8486
count = 63
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.609329/8485, current 216.625687/8486: elapsed=16351.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.625687
last_received_ts = 216.625061
last_seq = 8486
current_ts = 216.642029
current_received_ts = 216.641418
current_seq = 8487
count = 64
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.625687/8486, current 216.642029/8487: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.642029
last_received_ts = 216.641418
last_seq = 8487
current_ts = 216.658371
current_received_ts = 216.657761
current_seq = 8488
count = 65
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.642029/8487, current 216.658371/8488: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.658371
last_received_ts = 216.657761
last_seq = 8488
current_ts = 216.674728
current_received_ts = 216.674118
current_seq = 8489
count = 66
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.658371/8488, current 216.674728/8489: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.674728
last_received_ts = 216.674118
last_seq = 8489
current_ts = 216.691071
current_received_ts = 216.690460
current_seq = 8490
count = 67
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.674728/8489, current 216.691071/8490: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.691071
last_received_ts = 216.690460
last_seq = 8490
current_ts = 216.707428
current_received_ts = 216.706802
current_seq = 8491
count = 68
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.691071/8490, current 216.707428/8491: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.707428
last_received_ts = 216.706802
last_seq = 8491
current_ts = 216.723770
current_received_ts = 216.723160
current_seq = 8492
count = 69
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.707428/8491, current 216.723770/8492: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.723770
last_received_ts = 216.723160
last_seq = 8492
current_ts = 216.740128
current_received_ts = 216.739502
current_seq = 8493
count = 70
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.723770/8492, current 216.740128/8493: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.740128
last_received_ts = 216.739502
last_seq = 8493
current_ts = 216.756470
current_received_ts = 216.755859
current_seq = 8494
count = 71
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.740128/8493, current 216.756470/8494: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.756470
last_received_ts = 216.755859
last_seq = 8494
current_ts = 216.772827
current_received_ts = 216.772202
current_seq = 8495
count = 72
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.756470/8494, current 216.772827/8495: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.772827
last_received_ts = 216.772202
last_seq = 8495
current_ts = 216.789169
current_received_ts = 216.788559
current_seq = 8496
count = 73
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.772827/8495, current 216.789169/8496: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.789169
last_received_ts = 216.788559
last_seq = 8496
current_ts = 216.805511
current_received_ts = 216.804901
current_seq = 8497
count = 74
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.789169/8496, current 216.805511/8497: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.805511
last_received_ts = 216.804901
last_seq = 8497
current_ts = 216.821869
current_received_ts = 216.821259
current_seq = 8498
count = 75
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.805511/8497, current 216.821869/8498: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.821869
last_received_ts = 216.821259
last_seq = 8498
current_ts = 216.838211
current_received_ts = 216.837601
current_seq = 8499
count = 76
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.821869/8498, current 216.838211/8499: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.838211
last_received_ts = 216.837601
last_seq = 8499
current_ts = 216.854568
current_received_ts = 216.853958
current_seq = 8500
count = 77
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.838211/8499, current 216.854568/8500: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.854568
last_received_ts = 216.853958
last_seq = 8500
current_ts = 216.870911
current_received_ts = 216.870300
current_seq = 8501
count = 78
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.854568/8500, current 216.870911/8501: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.870911
last_received_ts = 216.870300
last_seq = 8501
current_ts = 216.887268
current_received_ts = 216.886642
current_seq = 8502
count = 79
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.870911/8501, current 216.887268/8502: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.887268
last_received_ts = 216.886642
last_seq = 8502
current_ts = 216.903610
current_received_ts = 216.903015
current_seq = 8503
count = 80
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.887268/8502, current 216.903610/8503: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.903610
last_received_ts = 216.903015
last_seq = 8503
current_ts = 216.919968
current_received_ts = 216.919342
current_seq = 8504
count = 81
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.903610/8503, current 216.919968/8504: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.919968
last_received_ts = 216.919342
last_seq = 8504
current_ts = 216.936310
current_received_ts = 216.935699
current_seq = 8505
count = 82
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.919968/8504, current 216.936310/8505: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.936310
last_received_ts = 216.935699
last_seq = 8505
current_ts = 216.952667
current_received_ts = 216.952072
current_seq = 8506
count = 83
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.936310/8505, current 216.952667/8506: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.952667
last_received_ts = 216.952072
last_seq = 8506
current_ts = 216.969009
current_received_ts = 216.968399
current_seq = 8507
count = 84
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.952667/8506, current 216.969009/8507: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.969009
last_received_ts = 216.968399
last_seq = 8507
current_ts = 216.985352
current_received_ts = 216.984741
current_seq = 8508
count = 85
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.969009/8507, current 216.985352/8508: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 216.985352
last_received_ts = 216.984741
last_seq = 8508
current_ts = 217.001709
current_received_ts = 217.001099
current_seq = 8509
count = 86
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 216.985352/8508, current 217.001709/8509: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.001709
last_received_ts = 217.001099
last_seq = 8509
current_ts = 217.018051
current_received_ts = 217.017441
current_seq = 8510
count = 87
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.001709/8509, current 217.018051/8510: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.018051
last_received_ts = 217.017441
last_seq = 8510
current_ts = 217.034409
current_received_ts = 217.033798
current_seq = 8511
count = 88
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.018051/8510, current 217.034409/8511: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.034409
last_received_ts = 217.033798
last_seq = 8511
current_ts = 217.050751
current_received_ts = 217.050140
current_seq = 8512
count = 89
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.034409/8511, current 217.050751/8512: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.050751
last_received_ts = 217.050140
last_seq = 8512
current_ts = 217.067108
current_received_ts = 217.066483
current_seq = 8513
count = 90
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.050751/8512, current 217.067108/8513: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.067108
last_received_ts = 217.066483
last_seq = 8513
current_ts = 217.083450
current_received_ts = 217.082840
current_seq = 8514
count = 91
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.067108/8513, current 217.083450/8514: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.083450
last_received_ts = 217.082840
last_seq = 8514
current_ts = 217.099808
current_received_ts = 217.099182
current_seq = 8515
count = 92
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.083450/8514, current 217.099808/8515: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.099808
last_received_ts = 217.099182
last_seq = 8515
current_ts = 217.116150
current_received_ts = 217.115540
current_seq = 8516
count = 93
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.099808/8515, current 217.116150/8516: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.116150
last_received_ts = 217.115540
last_seq = 8516
current_ts = 217.132492
current_received_ts = 217.131882
current_seq = 8517
count = 94
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.116150/8516, current 217.132492/8517: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.132492
last_received_ts = 217.131882
last_seq = 8517
current_ts = 217.148849
current_received_ts = 217.148239
current_seq = 8518
count = 95
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.132492/8517, current 217.148849/8518: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.148849
last_received_ts = 217.148239
last_seq = 8518
current_ts = 217.165192
current_received_ts = 217.164581
current_seq = 8519
count = 96
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.148849/8518, current 217.165192/8519: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.165192
last_received_ts = 217.164581
last_seq = 8519
current_ts = 217.181549
current_received_ts = 217.180939
current_seq = 8520
count = 97
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.165192/8519, current 217.181549/8520: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.181549
last_received_ts = 217.180939
last_seq = 8520
current_ts = 217.197891
current_received_ts = 217.197281
current_seq = 8521
count = 98
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.181549/8520, current 217.197891/8521: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.197891
last_received_ts = 217.197281
last_seq = 8521
current_ts = 217.214249
current_received_ts = 217.213638
current_seq = 8522
count = 99
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.197891/8521, current 217.214249/8522: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.214249
last_received_ts = 217.213638
last_seq = 8522
current_ts = 217.230591
current_received_ts = 217.229980
current_seq = 8523
count = 100
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.214249/8522, current 217.230591/8523: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.230591
last_received_ts = 217.229980
last_seq = 8523
current_ts = 217.246948
current_received_ts = 217.246323
current_seq = 8524
count = 101
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.230591/8523, current 217.246948/8524: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.246948
last_received_ts = 217.246323
last_seq = 8524
current_ts = 217.263290
current_received_ts = 217.262680
current_seq = 8525
count = 102
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.246948/8524, current 217.263290/8525: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.263290
last_received_ts = 217.262680
last_seq = 8525
current_ts = 217.279648
current_received_ts = 217.279053
current_seq = 8526
count = 103
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.263290/8525, current 217.279648/8526: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.279648
last_received_ts = 217.279053
last_seq = 8526
current_ts = 217.295990
current_received_ts = 217.295380
current_seq = 8527
count = 104
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.279648/8526, current 217.295990/8527: elapsed=16349.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.295990
last_received_ts = 217.295380
last_seq = 8527
current_ts = 217.312332
current_received_ts = 217.311722
current_seq = 8528
count = 105
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.295990/8527, current 217.312332/8528: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.312332
last_received_ts = 217.311722
last_seq = 8528
current_ts = 217.328690
current_received_ts = 217.328079
current_seq = 8529
count = 106
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.312332/8528, current 217.328690/8529: elapsed=16348.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.328690
last_received_ts = 217.328079
last_seq = 8529
current_ts = 217.345032
current_received_ts = 217.344421
current_seq = 8530
count = 107
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.328690/8529, current 217.345032/8530: elapsed=16350.0us expected=16294.6us +- 81.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.345032
last_received_ts = 217.344421
last_seq = 8530
current_ts = 217.361404
current_received_ts = 217.360779
current_seq = 8531
count = 108
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.345032/8530, current 217.361404/8531: elapsed=16360.0us expected=16294.6us +- 81.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 217.361404
last_received_ts = 217.360779
last_seq = 8531
current_ts = 217.377792
current_received_ts = 217.377167
current_seq = 8532
count = 109
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 217.361404/8531, current 217.377792/8532: elapsed=16389.0us expected=16294.6us +- 81.5us, error 0.6%
(kms_flip:4847) DEBUG: inconsistent flip ts/seq: last 217.361404/8531, current 217.377792/8532: elapsed=16389.0us expected=16294.6us
(kms_flip:4847) DEBUG: expected 26929, counted 109, encoder type 2
(kms_flip:4847) DEBUG: dropped frames, expected 26929, counted 109, encoder type 2
(kms_flip:4847) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:4847) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:4847) igt_core-INFO: Stack trace:
(kms_flip:4847) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:4847) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:4847) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:4847) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:4847) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:4847) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:4847) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:4847) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (6.975s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:4847) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:4847) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:4847) DEBUG: flip ts/seq: last 224.433228/8944, current 224.449783/8945: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.449783
last_received_ts = 224.449188
last_seq = 8945
current_ts = 224.466339
current_received_ts = 224.465729
current_seq = 8946
count = 122
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.449783/8945, current 224.466339/8946: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.466339
last_received_ts = 224.465729
last_seq = 8946
current_ts = 224.482895
current_received_ts = 224.482285
current_seq = 8947
count = 123
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.466339/8946, current 224.482895/8947: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.482895
last_received_ts = 224.482285
last_seq = 8947
current_ts = 224.499435
current_received_ts = 224.498840
current_seq = 8948
count = 124
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.482895/8947, current 224.499435/8948: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.499435
last_received_ts = 224.498840
last_seq = 8948
current_ts = 224.515991
current_received_ts = 224.515396
current_seq = 8949
count = 125
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.499435/8948, current 224.515991/8949: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.515991
last_received_ts = 224.515396
last_seq = 8949
current_ts = 224.532547
current_received_ts = 224.531937
current_seq = 8950
count = 126
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.515991/8949, current 224.532547/8950: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.532547
last_received_ts = 224.531937
last_seq = 8950
current_ts = 224.549103
current_received_ts = 224.548492
current_seq = 8951
count = 127
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.532547/8950, current 224.549103/8951: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.549103
last_received_ts = 224.548492
last_seq = 8951
current_ts = 224.565659
current_received_ts = 224.565048
current_seq = 8952
count = 128
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.549103/8951, current 224.565659/8952: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.565659
last_received_ts = 224.565048
last_seq = 8952
current_ts = 224.582199
current_received_ts = 224.581589
current_seq = 8953
count = 129
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.565659/8952, current 224.582199/8953: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.582199
last_received_ts = 224.581589
last_seq = 8953
current_ts = 224.598755
current_received_ts = 224.598145
current_seq = 8954
count = 130
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.582199/8953, current 224.598755/8954: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.598755
last_received_ts = 224.598145
last_seq = 8954
current_ts = 224.615311
current_received_ts = 224.614700
current_seq = 8955
count = 131
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.598755/8954, current 224.615311/8955: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.615311
last_received_ts = 224.614700
last_seq = 8955
current_ts = 224.631866
current_received_ts = 224.631256
current_seq = 8956
count = 132
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.615311/8955, current 224.631866/8956: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.631866
last_received_ts = 224.631256
last_seq = 8956
current_ts = 224.648422
current_received_ts = 224.647812
current_seq = 8957
count = 133
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.631866/8956, current 224.648422/8957: elapsed=16551.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.648422
last_received_ts = 224.647812
last_seq = 8957
current_ts = 224.664963
current_received_ts = 224.664352
current_seq = 8958
count = 134
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.648422/8957, current 224.664963/8958: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.664963
last_received_ts = 224.664352
last_seq = 8958
current_ts = 224.681519
current_received_ts = 224.680908
current_seq = 8959
count = 135
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.664963/8958, current 224.681519/8959: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.681519
last_received_ts = 224.680908
last_seq = 8959
current_ts = 224.698074
current_received_ts = 224.697464
current_seq = 8960
count = 136
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.681519/8959, current 224.698074/8960: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.698074
last_received_ts = 224.697464
last_seq = 8960
current_ts = 224.714630
current_received_ts = 224.714035
current_seq = 8961
count = 137
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.698074/8960, current 224.714630/8961: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.714630
last_received_ts = 224.714035
last_seq = 8961
current_ts = 224.731186
current_received_ts = 224.730576
current_seq = 8962
count = 138
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.714630/8961, current 224.731186/8962: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.731186
last_received_ts = 224.730576
last_seq = 8962
current_ts = 224.747726
current_received_ts = 224.747116
current_seq = 8963
count = 139
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.731186/8962, current 224.747726/8963: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.747726
last_received_ts = 224.747116
last_seq = 8963
current_ts = 224.764282
current_received_ts = 224.763672
current_seq = 8964
count = 140
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.747726/8963, current 224.764282/8964: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.764282
last_received_ts = 224.763672
last_seq = 8964
current_ts = 224.780838
current_received_ts = 224.780228
current_seq = 8965
count = 141
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.764282/8964, current 224.780838/8965: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.780838
last_received_ts = 224.780228
last_seq = 8965
current_ts = 224.797394
current_received_ts = 224.796783
current_seq = 8966
count = 142
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.780838/8965, current 224.797394/8966: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.797394
last_received_ts = 224.796783
last_seq = 8966
current_ts = 224.813950
current_received_ts = 224.813339
current_seq = 8967
count = 143
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.797394/8966, current 224.813950/8967: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.813950
last_received_ts = 224.813339
last_seq = 8967
current_ts = 224.830490
current_received_ts = 224.829880
current_seq = 8968
count = 144
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.813950/8967, current 224.830490/8968: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.830490
last_received_ts = 224.829880
last_seq = 8968
current_ts = 224.847046
current_received_ts = 224.846436
current_seq = 8969
count = 145
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.830490/8968, current 224.847046/8969: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.847046
last_received_ts = 224.846436
last_seq = 8969
current_ts = 224.863602
current_received_ts = 224.862991
current_seq = 8970
count = 146
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.847046/8969, current 224.863602/8970: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.863602
last_received_ts = 224.862991
last_seq = 8970
current_ts = 224.880157
current_received_ts = 224.879547
current_seq = 8971
count = 147
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.863602/8970, current 224.880157/8971: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.880157
last_received_ts = 224.879547
last_seq = 8971
current_ts = 224.896698
current_received_ts = 224.896164
current_seq = 8972
count = 148
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.880157/8971, current 224.896698/8972: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.896698
last_received_ts = 224.896164
last_seq = 8972
current_ts = 224.913254
current_received_ts = 224.912750
current_seq = 8973
count = 149
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.896698/8972, current 224.913254/8973: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.913254
last_received_ts = 224.912750
last_seq = 8973
current_ts = 224.929810
current_received_ts = 224.929337
current_seq = 8974
count = 150
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.913254/8973, current 224.929810/8974: elapsed=16559.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.929810
last_received_ts = 224.929337
last_seq = 8974
current_ts = 224.946365
current_received_ts = 224.945816
current_seq = 8975
count = 151
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.929810/8974, current 224.946365/8975: elapsed=16555.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.946365
last_received_ts = 224.945816
last_seq = 8975
current_ts = 224.962921
current_received_ts = 224.962372
current_seq = 8976
count = 152
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.946365/8975, current 224.962921/8976: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.962921
last_received_ts = 224.962372
last_seq = 8976
current_ts = 224.979477
current_received_ts = 224.978943
current_seq = 8977
count = 153
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.962921/8976, current 224.979477/8977: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.979477
last_received_ts = 224.978943
last_seq = 8977
current_ts = 224.996033
current_received_ts = 224.995468
current_seq = 8978
count = 154
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.979477/8977, current 224.996033/8978: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 224.996033
last_received_ts = 224.995468
last_seq = 8978
current_ts = 225.012589
current_received_ts = 225.012115
current_seq = 8979
count = 155
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 224.996033/8978, current 225.012589/8979: elapsed=16554.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.012589
last_received_ts = 225.012115
last_seq = 8979
current_ts = 225.029129
current_received_ts = 225.028641
current_seq = 8980
count = 156
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.012589/8979, current 225.029129/8980: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.029129
last_received_ts = 225.028641
last_seq = 8980
current_ts = 225.045670
current_received_ts = 225.045151
current_seq = 8981
count = 157
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.029129/8980, current 225.045670/8981: elapsed=16542.0us expected=16504.6us +- 82.5us, error 0.2%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.045670
last_received_ts = 225.045151
last_seq = 8981
current_ts = 225.062241
current_received_ts = 225.061691
current_seq = 8982
count = 158
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.045670/8981, current 225.062241/8982: elapsed=16561.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.062241
last_received_ts = 225.061691
last_seq = 8982
current_ts = 225.078781
current_received_ts = 225.078186
current_seq = 8983
count = 159
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.062241/8982, current 225.078781/8983: elapsed=16547.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.078781
last_received_ts = 225.078186
last_seq = 8983
current_ts = 225.095337
current_received_ts = 225.094727
current_seq = 8984
count = 160
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.078781/8983, current 225.095337/8984: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.095337
last_received_ts = 225.094727
last_seq = 8984
current_ts = 225.111893
current_received_ts = 225.111282
current_seq = 8985
count = 161
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.095337/8984, current 225.111893/8985: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.111893
last_received_ts = 225.111282
last_seq = 8985
current_ts = 225.128448
current_received_ts = 225.127838
current_seq = 8986
count = 162
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.111893/8985, current 225.128448/8986: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.128448
last_received_ts = 225.127838
last_seq = 8986
current_ts = 225.144989
current_received_ts = 225.144394
current_seq = 8987
count = 163
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.128448/8986, current 225.144989/8987: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.144989
last_received_ts = 225.144394
last_seq = 8987
current_ts = 225.161545
current_received_ts = 225.160934
current_seq = 8988
count = 164
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.144989/8987, current 225.161545/8988: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.161545
last_received_ts = 225.160934
last_seq = 8988
current_ts = 225.178101
current_received_ts = 225.177490
current_seq = 8989
count = 165
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.161545/8988, current 225.178101/8989: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.178101
last_received_ts = 225.177490
last_seq = 8989
current_ts = 225.194656
current_received_ts = 225.194061
current_seq = 8990
count = 166
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.178101/8989, current 225.194656/8990: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.194656
last_received_ts = 225.194061
last_seq = 8990
current_ts = 225.211197
current_received_ts = 225.210602
current_seq = 8991
count = 167
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.194656/8990, current 225.211197/8991: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.211197
last_received_ts = 225.210602
last_seq = 8991
current_ts = 225.227753
current_received_ts = 225.227158
current_seq = 8992
count = 168
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.211197/8991, current 225.227753/8992: elapsed=16556.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.227753
last_received_ts = 225.227158
last_seq = 8992
current_ts = 225.244308
current_received_ts = 225.243698
current_seq = 8993
count = 169
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.227753/8992, current 225.244308/8993: elapsed=16549.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.244308
last_received_ts = 225.243698
last_seq = 8993
current_ts = 225.260864
current_received_ts = 225.260254
current_seq = 8994
count = 170
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.244308/8993, current 225.260864/8994: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.260864
last_received_ts = 225.260254
last_seq = 8994
current_ts = 225.277420
current_received_ts = 225.276810
current_seq = 8995
count = 171
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.260864/8994, current 225.277420/8995: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.277420
last_received_ts = 225.276810
last_seq = 8995
current_ts = 225.293961
current_received_ts = 225.293365
current_seq = 8996
count = 172
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.277420/8995, current 225.293961/8996: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.293961
last_received_ts = 225.293365
last_seq = 8996
current_ts = 225.310516
current_received_ts = 225.309921
current_seq = 8997
count = 173
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.293961/8996, current 225.310516/8997: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.310516
last_received_ts = 225.309921
last_seq = 8997
current_ts = 225.327072
current_received_ts = 225.326462
current_seq = 8998
count = 174
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.310516/8997, current 225.327072/8998: elapsed=16553.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.327072
last_received_ts = 225.326462
last_seq = 8998
current_ts = 225.343628
current_received_ts = 225.343033
current_seq = 8999
count = 175
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.327072/8998, current 225.343628/8999: elapsed=16552.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.343628
last_received_ts = 225.343033
last_seq = 8999
current_ts = 225.360184
current_received_ts = 225.359573
current_seq = 9000
count = 176
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.343628/8999, current 225.360184/9000: elapsed=16555.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.360184
last_received_ts = 225.359573
last_seq = 9000
current_ts = 225.376755
current_received_ts = 225.376144
current_seq = 9001
count = 177
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.360184/9000, current 225.376755/9001: elapsed=16572.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.376755
last_received_ts = 225.376144
last_seq = 9001
current_ts = 225.393311
current_received_ts = 225.392700
current_seq = 9002
count = 178
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.376755/9001, current 225.393311/9002: elapsed=16559.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.393311
last_received_ts = 225.392700
last_seq = 9002
current_ts = 225.409882
current_received_ts = 225.409271
current_seq = 9003
count = 179
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.393311/9002, current 225.409882/9003: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.409882
last_received_ts = 225.409271
last_seq = 9003
current_ts = 225.426437
current_received_ts = 225.425842
current_seq = 9004
count = 180
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.409882/9003, current 225.426437/9004: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.426437
last_received_ts = 225.425842
last_seq = 9004
current_ts = 225.443008
current_received_ts = 225.442398
current_seq = 9005
count = 181
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.426437/9004, current 225.443008/9005: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.443008
last_received_ts = 225.442398
last_seq = 9005
current_ts = 225.459579
current_received_ts = 225.458969
current_seq = 9006
count = 182
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.443008/9005, current 225.459579/9006: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.459579
last_received_ts = 225.458969
last_seq = 9006
current_ts = 225.476135
current_received_ts = 225.475540
current_seq = 9007
count = 183
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.459579/9006, current 225.476135/9007: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.476135
last_received_ts = 225.475540
last_seq = 9007
current_ts = 225.492706
current_received_ts = 225.492111
current_seq = 9008
count = 184
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.476135/9007, current 225.492706/9008: elapsed=16570.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.492706
last_received_ts = 225.492111
last_seq = 9008
current_ts = 225.509277
current_received_ts = 225.508667
current_seq = 9009
count = 185
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.492706/9008, current 225.509277/9009: elapsed=16562.0us expected=16504.6us +- 82.5us, error 0.3%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.509277
last_received_ts = 225.508667
last_seq = 9009
current_ts = 225.525833
current_received_ts = 225.525223
current_seq = 9010
count = 186
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.509277/9009, current 225.525833/9010: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.525833
last_received_ts = 225.525223
last_seq = 9010
current_ts = 225.542404
current_received_ts = 225.541794
current_seq = 9011
count = 187
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.525833/9010, current 225.542404/9011: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.542404
last_received_ts = 225.541794
last_seq = 9011
current_ts = 225.558975
current_received_ts = 225.558365
current_seq = 9012
count = 188
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.542404/9011, current 225.558975/9012: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.558975
last_received_ts = 225.558365
last_seq = 9012
current_ts = 225.575531
current_received_ts = 225.574936
current_seq = 9013
count = 189
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.558975/9012, current 225.575531/9013: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.575531
last_received_ts = 225.574936
last_seq = 9013
current_ts = 225.592102
current_received_ts = 225.591492
current_seq = 9014
count = 190
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.575531/9013, current 225.592102/9014: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.592102
last_received_ts = 225.591492
last_seq = 9014
current_ts = 225.608673
current_received_ts = 225.608078
current_seq = 9015
count = 191
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.592102/9014, current 225.608673/9015: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.608673
last_received_ts = 225.608078
last_seq = 9015
current_ts = 225.625229
current_received_ts = 225.624634
current_seq = 9016
count = 192
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.608673/9015, current 225.625229/9016: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.625229
last_received_ts = 225.624634
last_seq = 9016
current_ts = 225.641800
current_received_ts = 225.641190
current_seq = 9017
count = 193
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.625229/9016, current 225.641800/9017: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.641800
last_received_ts = 225.641190
last_seq = 9017
current_ts = 225.658371
current_received_ts = 225.657761
current_seq = 9018
count = 194
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.641800/9017, current 225.658371/9018: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.658371
last_received_ts = 225.657761
last_seq = 9018
current_ts = 225.674927
current_received_ts = 225.674347
current_seq = 9019
count = 195
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.658371/9018, current 225.674927/9019: elapsed=16568.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.674927
last_received_ts = 225.674347
last_seq = 9019
current_ts = 225.691498
current_received_ts = 225.690887
current_seq = 9020
count = 196
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.674927/9019, current 225.691498/9020: elapsed=16564.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.691498
last_received_ts = 225.690887
last_seq = 9020
current_ts = 225.708069
current_received_ts = 225.707458
current_seq = 9021
count = 197
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.691498/9020, current 225.708069/9021: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.708069
last_received_ts = 225.707458
last_seq = 9021
current_ts = 225.724625
current_received_ts = 225.724030
current_seq = 9022
count = 198
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.708069/9021, current 225.724625/9022: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.724625
last_received_ts = 225.724030
last_seq = 9022
current_ts = 225.741196
current_received_ts = 225.740601
current_seq = 9023
count = 199
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.724625/9022, current 225.741196/9023: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.741196
last_received_ts = 225.740601
last_seq = 9023
current_ts = 225.757767
current_received_ts = 225.757156
current_seq = 9024
count = 200
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.741196/9023, current 225.757767/9024: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.757767
last_received_ts = 225.757156
last_seq = 9024
current_ts = 225.774323
current_received_ts = 225.773727
current_seq = 9025
count = 201
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.757767/9024, current 225.774323/9025: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.774323
last_received_ts = 225.773727
last_seq = 9025
current_ts = 225.790894
current_received_ts = 225.790283
current_seq = 9026
count = 202
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.774323/9025, current 225.790894/9026: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.790894
last_received_ts = 225.790283
last_seq = 9026
current_ts = 225.807465
current_received_ts = 225.806854
current_seq = 9027
count = 203
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.790894/9026, current 225.807465/9027: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.807465
last_received_ts = 225.806854
last_seq = 9027
current_ts = 225.824020
current_received_ts = 225.823425
current_seq = 9028
count = 204
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.807465/9027, current 225.824020/9028: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.824020
last_received_ts = 225.823425
last_seq = 9028
current_ts = 225.840591
current_received_ts = 225.839981
current_seq = 9029
count = 205
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.824020/9028, current 225.840591/9029: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.840591
last_received_ts = 225.839981
last_seq = 9029
current_ts = 225.857162
current_received_ts = 225.856552
current_seq = 9030
count = 206
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.840591/9029, current 225.857162/9030: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.857162
last_received_ts = 225.856552
last_seq = 9030
current_ts = 225.873718
current_received_ts = 225.873123
current_seq = 9031
count = 207
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.857162/9030, current 225.873718/9031: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.873718
last_received_ts = 225.873123
last_seq = 9031
current_ts = 225.890289
current_received_ts = 225.889679
current_seq = 9032
count = 208
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.873718/9031, current 225.890289/9032: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.890289
last_received_ts = 225.889679
last_seq = 9032
current_ts = 225.906860
current_received_ts = 225.906250
current_seq = 9033
count = 209
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.890289/9032, current 225.906860/9033: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.906860
last_received_ts = 225.906250
last_seq = 9033
current_ts = 225.923416
current_received_ts = 225.922821
current_seq = 9034
count = 210
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.906860/9033, current 225.923416/9034: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.923416
last_received_ts = 225.922821
last_seq = 9034
current_ts = 225.939987
current_received_ts = 225.939545
current_seq = 9035
count = 211
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.923416/9034, current 225.939987/9035: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.939987
last_received_ts = 225.939545
last_seq = 9035
current_ts = 225.956558
current_received_ts = 225.955963
current_seq = 9036
count = 212
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.939987/9035, current 225.956558/9036: elapsed=16570.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.956558
last_received_ts = 225.955963
last_seq = 9036
current_ts = 225.973129
current_received_ts = 225.972519
current_seq = 9037
count = 213
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.956558/9036, current 225.973129/9037: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.973129
last_received_ts = 225.972519
last_seq = 9037
current_ts = 225.989685
current_received_ts = 225.989090
current_seq = 9038
count = 214
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.973129/9037, current 225.989685/9038: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 225.989685
last_received_ts = 225.989090
last_seq = 9038
current_ts = 226.006256
current_received_ts = 226.005768
current_seq = 9039
count = 215
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 225.989685/9038, current 226.006256/9039: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.006256
last_received_ts = 226.005768
last_seq = 9039
current_ts = 226.022812
current_received_ts = 226.022247
current_seq = 9040
count = 216
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.006256/9039, current 226.022812/9040: elapsed=16564.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.022812
last_received_ts = 226.022247
last_seq = 9040
current_ts = 226.039383
current_received_ts = 226.038879
current_seq = 9041
count = 217
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.022812/9040, current 226.039383/9041: elapsed=16564.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.039383
last_received_ts = 226.038879
last_seq = 9041
current_ts = 226.055954
current_received_ts = 226.055450
current_seq = 9042
count = 218
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.039383/9041, current 226.055954/9042: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.055954
last_received_ts = 226.055450
last_seq = 9042
current_ts = 226.072510
current_received_ts = 226.071960
current_seq = 9043
count = 219
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.055954/9042, current 226.072510/9043: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.072510
last_received_ts = 226.071960
last_seq = 9043
current_ts = 226.089081
current_received_ts = 226.088516
current_seq = 9044
count = 220
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.072510/9043, current 226.089081/9044: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.089081
last_received_ts = 226.088516
last_seq = 9044
current_ts = 226.105652
current_received_ts = 226.105057
current_seq = 9045
count = 221
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.089081/9044, current 226.105652/9045: elapsed=16568.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.105652
last_received_ts = 226.105057
last_seq = 9045
current_ts = 226.122208
current_received_ts = 226.121613
current_seq = 9046
count = 222
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.105652/9045, current 226.122208/9046: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.122208
last_received_ts = 226.121613
last_seq = 9046
current_ts = 226.138779
current_received_ts = 226.138168
current_seq = 9047
count = 223
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.122208/9046, current 226.138779/9047: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.138779
last_received_ts = 226.138168
last_seq = 9047
current_ts = 226.155350
current_received_ts = 226.154739
current_seq = 9048
count = 224
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.138779/9047, current 226.155350/9048: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.155350
last_received_ts = 226.154739
last_seq = 9048
current_ts = 226.171906
current_received_ts = 226.171310
current_seq = 9049
count = 225
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.155350/9048, current 226.171906/9049: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.171906
last_received_ts = 226.171310
last_seq = 9049
current_ts = 226.188477
current_received_ts = 226.187866
current_seq = 9050
count = 226
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.171906/9049, current 226.188477/9050: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.188477
last_received_ts = 226.187866
last_seq = 9050
current_ts = 226.205048
current_received_ts = 226.204437
current_seq = 9051
count = 227
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.188477/9050, current 226.205048/9051: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.205048
last_received_ts = 226.204437
last_seq = 9051
current_ts = 226.221603
current_received_ts = 226.221039
current_seq = 9052
count = 228
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.205048/9051, current 226.221603/9052: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.221603
last_received_ts = 226.221039
last_seq = 9052
current_ts = 226.238174
current_received_ts = 226.237564
current_seq = 9053
count = 229
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.221603/9052, current 226.238174/9053: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.238174
last_received_ts = 226.237564
last_seq = 9053
current_ts = 226.254745
current_received_ts = 226.254135
current_seq = 9054
count = 230
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.238174/9053, current 226.254745/9054: elapsed=16568.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.254745
last_received_ts = 226.254135
last_seq = 9054
current_ts = 226.271301
current_received_ts = 226.270691
current_seq = 9055
count = 231
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.254745/9054, current 226.271301/9055: elapsed=16563.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.271301
last_received_ts = 226.270691
last_seq = 9055
current_ts = 226.287872
current_received_ts = 226.287262
current_seq = 9056
count = 232
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.271301/9055, current 226.287872/9056: elapsed=16566.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.287872
last_received_ts = 226.287262
last_seq = 9056
current_ts = 226.304443
current_received_ts = 226.303909
current_seq = 9057
count = 233
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.287872/9056, current 226.304443/9057: elapsed=16567.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.304443
last_received_ts = 226.303909
last_seq = 9057
current_ts = 226.320999
current_received_ts = 226.320465
current_seq = 9058
count = 234
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.304443/9057, current 226.320999/9058: elapsed=16563.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.320999
last_received_ts = 226.320465
last_seq = 9058
current_ts = 226.337570
current_received_ts = 226.337051
current_seq = 9059
count = 235
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.320999/9058, current 226.337570/9059: elapsed=16563.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.337570
last_received_ts = 226.337051
last_seq = 9059
current_ts = 226.354141
current_received_ts = 226.353607
current_seq = 9060
count = 236
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.337570/9059, current 226.354141/9060: elapsed=16577.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.354141
last_received_ts = 226.353607
last_seq = 9060
current_ts = 226.370712
current_received_ts = 226.370163
current_seq = 9061
count = 237
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.354141/9060, current 226.370712/9061: elapsed=16565.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.370712
last_received_ts = 226.370163
last_seq = 9061
current_ts = 226.387283
current_received_ts = 226.386749
current_seq = 9062
count = 238
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.370712/9061, current 226.387283/9062: elapsed=16578.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.387283
last_received_ts = 226.386749
last_seq = 9062
current_ts = 226.403854
current_received_ts = 226.403320
current_seq = 9063
count = 239
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.387283/9062, current 226.403854/9063: elapsed=16576.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.403854
last_received_ts = 226.403320
last_seq = 9063
current_ts = 226.420441
current_received_ts = 226.419891
current_seq = 9064
count = 240
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.403854/9063, current 226.420441/9064: elapsed=16578.0us expected=16504.6us +- 82.5us, error 0.4%
(kms_flip:4847) DEBUG: name = flip
last_ts = 226.420441
last_received_ts = 226.419891
last_seq = 9064
current_ts = 226.437027
current_received_ts = 226.436493
current_seq = 9065
count = 241
seq_step = 1
(kms_flip:4847) DEBUG: flip ts/seq: last 226.420441/9064, current 226.437027/9065: elapsed=16589.0us expected=16504.6us +- 82.5us, error 0.5%
(kms_flip:4847) DEBUG: inconsistent flip ts/seq: last 226.420441/9064, current 226.437027/9065: elapsed=16589.0us expected=16504.6us
(kms_flip:4847) DEBUG: expected 26586, counted 241, encoder type 2
(kms_flip:4847) DEBUG: dropped frames, expected 26586, counted 241, encoder type 2
(kms_flip:4847) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:4847) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:4847) igt_core-INFO: Stack trace:
(kms_flip:4847) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:4847) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:4847) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:4847) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:4847) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:4847) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:4847) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:4847) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (9.018s)
Starting dynamic subtest: AD-DP2-HDMI-A3
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.688s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.692s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.680s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.659s)
Subtest 2x-plain-flip-ts-check: FAIL (38.771s)