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

shard-bmg-7

IGT-Version: 2.0-gfda353526 (x86_64) (Linux: 6.14.0-rc6-xe+ x86_64)

Using IGT_SRANDOM=1742039800 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 17229.0us +- 8.485us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 17229us +- 8.485us, difference 562.3us (66.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AB-DP2-HDMI-A3: FAIL (6.492s)
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 16923.5us +- 6.346us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16924us +- 6.346us, difference 256.8us (40.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AC-DP2-HDMI-A3: FAIL (7.346s)
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 16761.5us +- 7.625us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16761us +- 7.625us, difference 94.8us (12.4 sigma)
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.659s)
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 16719.5us +- 4.633us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16720us +- 4.633us, difference 52.8us (11.4 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.674s)
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 16695.2us +- 5.671us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16695us +- 5.671us, difference 28.5us (5.0 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 16673.2us +- 6.025us accuracy 0.11%
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.650s)
Subtest 2x-plain-flip-ts-check: FAIL (36.514s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:5575) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:5575) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:5575) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:5575) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:5575) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:5575) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:5575) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:5575) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:5575) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f267cc80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f267cc80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f268ab40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f268ab40, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f26c1060, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f26c1060, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f26c1a50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) intel_allocator_simple-DEBUG: <ial: 0x5768f26c1a50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5575) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:5575) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:5575) DEBUG: No stale events found
(kms_flip:5575) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:5575) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:5575) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:5575) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:5575) INFO: Expected frametime: 16667us; measured 17229.0us +- 8.485us accuracy 0.15%
(kms_flip:5575) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17229us +- 8.485us, difference 562.3us (66.3 sigma)
(kms_flip:5575) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 142.510849
current_received_ts = 142.510361
current_seq = 4216
count = 0
seq_step = 1
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.510849
last_received_ts = 142.510361
last_seq = 4216
current_ts = 142.528091
current_received_ts = 142.527603
current_seq = 4217
count = 1
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.510849/4216, current 142.528091/4217: elapsed=17233.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.528091
last_received_ts = 142.527603
last_seq = 4217
current_ts = 142.545303
current_received_ts = 142.544815
current_seq = 4218
count = 2
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.528091/4217, current 142.545303/4218: elapsed=17222.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.545303
last_received_ts = 142.544815
last_seq = 4218
current_ts = 142.562546
current_received_ts = 142.562057
current_seq = 4219
count = 3
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.545303/4218, current 142.562546/4219: elapsed=17242.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.562546
last_received_ts = 142.562057
last_seq = 4219
current_ts = 142.579773
current_received_ts = 142.579254
current_seq = 4220
count = 4
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.562546/4219, current 142.579773/4220: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.579773
last_received_ts = 142.579254
last_seq = 4220
current_ts = 142.597000
current_received_ts = 142.596497
current_seq = 4221
count = 5
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.579773/4220, current 142.597000/4221: elapsed=17219.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.597000
last_received_ts = 142.596497
last_seq = 4221
current_ts = 142.614227
current_received_ts = 142.613724
current_seq = 4222
count = 6
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.597000/4221, current 142.614227/4222: elapsed=17227.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.614227
last_received_ts = 142.613724
last_seq = 4222
current_ts = 142.631439
current_received_ts = 142.630905
current_seq = 4223
count = 7
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.614227/4222, current 142.631439/4223: elapsed=17223.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.631439
last_received_ts = 142.630905
last_seq = 4223
current_ts = 142.648682
current_received_ts = 142.648178
current_seq = 4224
count = 8
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.631439/4223, current 142.648682/4224: elapsed=17233.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.648682
last_received_ts = 142.648178
last_seq = 4224
current_ts = 142.665909
current_received_ts = 142.665405
current_seq = 4225
count = 9
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.648682/4224, current 142.665909/4225: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.665909
last_received_ts = 142.665405
last_seq = 4225
current_ts = 142.683136
current_received_ts = 142.682632
current_seq = 4226
count = 10
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.665909/4225, current 142.683136/4226: elapsed=17229.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.683136
last_received_ts = 142.682632
last_seq = 4226
current_ts = 142.700363
current_received_ts = 142.699829
current_seq = 4227
count = 11
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.683136/4226, current 142.700363/4227: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.700363
last_received_ts = 142.699829
last_seq = 4227
current_ts = 142.717590
current_received_ts = 142.716980
current_seq = 4228
count = 12
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.700363/4227, current 142.717590/4228: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.717590
last_received_ts = 142.716980
last_seq = 4228
current_ts = 142.734818
current_received_ts = 142.734207
current_seq = 4229
count = 13
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.717590/4228, current 142.734818/4229: elapsed=17229.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.734818
last_received_ts = 142.734207
last_seq = 4229
current_ts = 142.752045
current_received_ts = 142.751434
current_seq = 4230
count = 14
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.734818/4229, current 142.752045/4230: elapsed=17225.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.752045
last_received_ts = 142.751434
last_seq = 4230
current_ts = 142.769272
current_received_ts = 142.768677
current_seq = 4231
count = 15
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.752045/4230, current 142.769272/4231: elapsed=17232.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.769272
last_received_ts = 142.768677
last_seq = 4231
current_ts = 142.786499
current_received_ts = 142.785995
current_seq = 4232
count = 16
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.769272/4231, current 142.786499/4232: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.786499
last_received_ts = 142.785995
last_seq = 4232
current_ts = 142.803726
current_received_ts = 142.803223
current_seq = 4233
count = 17
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.786499/4232, current 142.803726/4233: elapsed=17225.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.803726
last_received_ts = 142.803223
last_seq = 4233
current_ts = 142.820953
current_received_ts = 142.820557
current_seq = 4234
count = 18
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.803726/4233, current 142.820953/4234: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.820953
last_received_ts = 142.820557
last_seq = 4234
current_ts = 142.838181
current_received_ts = 142.837692
current_seq = 4235
count = 19
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.820953/4234, current 142.838181/4235: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.838181
last_received_ts = 142.837692
last_seq = 4235
current_ts = 142.855408
current_received_ts = 142.854813
current_seq = 4236
count = 20
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.838181/4235, current 142.855408/4236: elapsed=17234.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.855408
last_received_ts = 142.854813
last_seq = 4236
current_ts = 142.872650
current_received_ts = 142.872131
current_seq = 4237
count = 21
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.855408/4236, current 142.872650/4237: elapsed=17235.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.872650
last_received_ts = 142.872131
last_seq = 4237
current_ts = 142.889862
current_received_ts = 142.889359
current_seq = 4238
count = 22
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.872650/4237, current 142.889862/4238: elapsed=17218.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.889862
last_received_ts = 142.889359
last_seq = 4238
current_ts = 142.907089
current_received_ts = 142.906586
current_seq = 4239
count = 23
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.889862/4238, current 142.907089/4239: elapsed=17224.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.907089
last_received_ts = 142.906586
last_seq = 4239
current_ts = 142.924316
current_received_ts = 142.923813
current_seq = 4240
count = 24
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.907089/4239, current 142.924316/4240: elapsed=17230.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.924316
last_received_ts = 142.923813
last_seq = 4240
current_ts = 142.941544
current_received_ts = 142.941071
current_seq = 4241
count = 25
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.924316/4240, current 142.941544/4241: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.941544
last_received_ts = 142.941071
last_seq = 4241
current_ts = 142.958771
current_received_ts = 142.958267
current_seq = 4242
count = 26
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.941544/4241, current 142.958771/4242: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.958771
last_received_ts = 142.958267
last_seq = 4242
current_ts = 142.976013
current_received_ts = 142.975494
current_seq = 4243
count = 27
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.958771/4242, current 142.976013/4243: elapsed=17239.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.976013
last_received_ts = 142.975494
last_seq = 4243
current_ts = 142.993240
current_received_ts = 142.992722
current_seq = 4244
count = 28
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.976013/4243, current 142.993240/4244: elapsed=17221.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 142.993240
last_received_ts = 142.992722
last_seq = 4244
current_ts = 143.010468
current_received_ts = 143.009949
current_seq = 4245
count = 29
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 142.993240/4244, current 143.010468/4245: elapsed=17236.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.010468
last_received_ts = 143.009949
last_seq = 4245
current_ts = 143.027695
current_received_ts = 143.027176
current_seq = 4246
count = 30
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.010468/4245, current 143.027695/4246: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.027695
last_received_ts = 143.027176
last_seq = 4246
current_ts = 143.044922
current_received_ts = 143.044403
current_seq = 4247
count = 31
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.027695/4246, current 143.044922/4247: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.044922
last_received_ts = 143.044403
last_seq = 4247
current_ts = 143.062149
current_received_ts = 143.061646
current_seq = 4248
count = 32
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.044922/4247, current 143.062149/4248: elapsed=17221.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.062149
last_received_ts = 143.061646
last_seq = 4248
current_ts = 143.079376
current_received_ts = 143.078873
current_seq = 4249
count = 33
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.062149/4248, current 143.079376/4249: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.079376
last_received_ts = 143.078873
last_seq = 4249
current_ts = 143.096603
current_received_ts = 143.096085
current_seq = 4250
count = 34
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.079376/4249, current 143.096603/4250: elapsed=17234.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.096603
last_received_ts = 143.096085
last_seq = 4250
current_ts = 143.113831
current_received_ts = 143.113342
current_seq = 4251
count = 35
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.096603/4250, current 143.113831/4251: elapsed=17217.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.113831
last_received_ts = 143.113342
last_seq = 4251
current_ts = 143.131058
current_received_ts = 143.130554
current_seq = 4252
count = 36
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.113831/4251, current 143.131058/4252: elapsed=17228.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.131058
last_received_ts = 143.130554
last_seq = 4252
current_ts = 143.148285
current_received_ts = 143.147766
current_seq = 4253
count = 37
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.131058/4252, current 143.148285/4253: elapsed=17238.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.148285
last_received_ts = 143.147766
last_seq = 4253
current_ts = 143.165512
current_received_ts = 143.165009
current_seq = 4254
count = 38
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.148285/4253, current 143.165512/4254: elapsed=17215.0us expected=17229.0us +- 86.1us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.165512
last_received_ts = 143.165009
last_seq = 4254
current_ts = 143.182739
current_received_ts = 143.182373
current_seq = 4255
count = 39
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.165512/4254, current 143.182739/4255: elapsed=17232.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.182739
last_received_ts = 143.182373
last_seq = 4255
current_ts = 143.199966
current_received_ts = 143.199509
current_seq = 4256
count = 40
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.182739/4255, current 143.199966/4256: elapsed=17226.0us expected=17229.0us +- 86.1us, error 0.0%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.199966
last_received_ts = 143.199509
last_seq = 4256
current_ts = 143.217148
current_received_ts = 143.216644
current_seq = 4257
count = 41
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.199966/4256, current 143.217148/4257: elapsed=17180.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.217148
last_received_ts = 143.216644
last_seq = 4257
current_ts = 143.234299
current_received_ts = 143.233795
current_seq = 4258
count = 42
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.217148/4257, current 143.234299/4258: elapsed=17153.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.234299
last_received_ts = 143.233795
last_seq = 4258
current_ts = 143.251465
current_received_ts = 143.250961
current_seq = 4259
count = 43
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.234299/4258, current 143.251465/4259: elapsed=17162.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.251465
last_received_ts = 143.250961
last_seq = 4259
current_ts = 143.268631
current_received_ts = 143.268127
current_seq = 4260
count = 44
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.251465/4259, current 143.268631/4260: elapsed=17168.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.268631
last_received_ts = 143.268127
last_seq = 4260
current_ts = 143.285767
current_received_ts = 143.285263
current_seq = 4261
count = 45
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.268631/4260, current 143.285767/4261: elapsed=17146.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.285767
last_received_ts = 143.285263
last_seq = 4261
current_ts = 143.302933
current_received_ts = 143.302429
current_seq = 4262
count = 46
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.285767/4261, current 143.302933/4262: elapsed=17162.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.302933
last_received_ts = 143.302429
last_seq = 4262
current_ts = 143.320099
current_received_ts = 143.319595
current_seq = 4263
count = 47
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.302933/4262, current 143.320099/4263: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.320099
last_received_ts = 143.319595
last_seq = 4263
current_ts = 143.337265
current_received_ts = 143.336746
current_seq = 4264
count = 48
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.320099/4263, current 143.337265/4264: elapsed=17167.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.337265
last_received_ts = 143.336746
last_seq = 4264
current_ts = 143.354416
current_received_ts = 143.353897
current_seq = 4265
count = 49
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.337265/4264, current 143.354416/4265: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.354416
last_received_ts = 143.353897
last_seq = 4265
current_ts = 143.371567
current_received_ts = 143.371078
current_seq = 4266
count = 50
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.354416/4265, current 143.371567/4266: elapsed=17146.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.371567
last_received_ts = 143.371078
last_seq = 4266
current_ts = 143.388733
current_received_ts = 143.388321
current_seq = 4267
count = 51
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.371567/4266, current 143.388733/4267: elapsed=17172.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.388733
last_received_ts = 143.388321
last_seq = 4267
current_ts = 143.405884
current_received_ts = 143.405457
current_seq = 4268
count = 52
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.388733/4267, current 143.405884/4268: elapsed=17151.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.405884
last_received_ts = 143.405457
last_seq = 4268
current_ts = 143.423050
current_received_ts = 143.422638
current_seq = 4269
count = 53
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.405884/4268, current 143.423050/4269: elapsed=17166.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.423050
last_received_ts = 143.422638
last_seq = 4269
current_ts = 143.440201
current_received_ts = 143.439758
current_seq = 4270
count = 54
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.423050/4269, current 143.440201/4270: elapsed=17152.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.440201
last_received_ts = 143.439758
last_seq = 4270
current_ts = 143.457367
current_received_ts = 143.456879
current_seq = 4271
count = 55
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.440201/4270, current 143.457367/4271: elapsed=17156.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.457367
last_received_ts = 143.456879
last_seq = 4271
current_ts = 143.474518
current_received_ts = 143.474014
current_seq = 4272
count = 56
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.457367/4271, current 143.474518/4272: elapsed=17155.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.474518
last_received_ts = 143.474014
last_seq = 4272
current_ts = 143.491684
current_received_ts = 143.491272
current_seq = 4273
count = 57
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.474518/4272, current 143.491684/4273: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.491684
last_received_ts = 143.491272
last_seq = 4273
current_ts = 143.508835
current_received_ts = 143.508392
current_seq = 4274
count = 58
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.491684/4273, current 143.508835/4274: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.508835
last_received_ts = 143.508392
last_seq = 4274
current_ts = 143.526001
current_received_ts = 143.525497
current_seq = 4275
count = 59
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.508835/4274, current 143.526001/4275: elapsed=17156.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.526001
last_received_ts = 143.525497
last_seq = 4275
current_ts = 143.543167
current_received_ts = 143.542664
current_seq = 4276
count = 60
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.526001/4275, current 143.543167/4276: elapsed=17166.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.543167
last_received_ts = 143.542664
last_seq = 4276
current_ts = 143.560318
current_received_ts = 143.559814
current_seq = 4277
count = 61
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.543167/4276, current 143.560318/4277: elapsed=17152.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.560318
last_received_ts = 143.559814
last_seq = 4277
current_ts = 143.577484
current_received_ts = 143.576981
current_seq = 4278
count = 62
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.560318/4277, current 143.577484/4278: elapsed=17163.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.577484
last_received_ts = 143.576981
last_seq = 4278
current_ts = 143.594635
current_received_ts = 143.594147
current_seq = 4279
count = 63
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.577484/4278, current 143.594635/4279: elapsed=17160.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.594635
last_received_ts = 143.594147
last_seq = 4279
current_ts = 143.611801
current_received_ts = 143.611328
current_seq = 4280
count = 64
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.594635/4279, current 143.611801/4280: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.611801
last_received_ts = 143.611328
last_seq = 4280
current_ts = 143.628952
current_received_ts = 143.628433
current_seq = 4281
count = 65
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.611801/4280, current 143.628952/4281: elapsed=17152.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.628952
last_received_ts = 143.628433
last_seq = 4281
current_ts = 143.646118
current_received_ts = 143.645599
current_seq = 4282
count = 66
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.628952/4281, current 143.646118/4282: elapsed=17170.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.646118
last_received_ts = 143.645599
last_seq = 4282
current_ts = 143.663269
current_received_ts = 143.662766
current_seq = 4283
count = 67
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.646118/4282, current 143.663269/4283: elapsed=17146.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.663269
last_received_ts = 143.662766
last_seq = 4283
current_ts = 143.680420
current_received_ts = 143.679916
current_seq = 4284
count = 68
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.663269/4283, current 143.680420/4284: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.680420
last_received_ts = 143.679916
last_seq = 4284
current_ts = 143.697586
current_received_ts = 143.697098
current_seq = 4285
count = 69
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.680420/4284, current 143.697586/4285: elapsed=17160.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.697586
last_received_ts = 143.697098
last_seq = 4285
current_ts = 143.714752
current_received_ts = 143.714218
current_seq = 4286
count = 70
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.697586/4285, current 143.714752/4286: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.714752
last_received_ts = 143.714218
last_seq = 4286
current_ts = 143.731903
current_received_ts = 143.731400
current_seq = 4287
count = 71
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.714752/4286, current 143.731903/4287: elapsed=17153.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.731903
last_received_ts = 143.731400
last_seq = 4287
current_ts = 143.749054
current_received_ts = 143.748550
current_seq = 4288
count = 72
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.731903/4287, current 143.749054/4288: elapsed=17162.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.749054
last_received_ts = 143.748550
last_seq = 4288
current_ts = 143.766220
current_received_ts = 143.765717
current_seq = 4289
count = 73
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.749054/4288, current 143.766220/4289: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.766220
last_received_ts = 143.765717
last_seq = 4289
current_ts = 143.783371
current_received_ts = 143.782867
current_seq = 4290
count = 74
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.766220/4289, current 143.783371/4290: elapsed=17157.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.783371
last_received_ts = 143.782867
last_seq = 4290
current_ts = 143.800537
current_received_ts = 143.800079
current_seq = 4291
count = 75
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.783371/4290, current 143.800537/4291: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.800537
last_received_ts = 143.800079
last_seq = 4291
current_ts = 143.817703
current_received_ts = 143.817291
current_seq = 4292
count = 76
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.800537/4291, current 143.817703/4292: elapsed=17169.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.817703
last_received_ts = 143.817291
last_seq = 4292
current_ts = 143.834869
current_received_ts = 143.834335
current_seq = 4293
count = 77
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.817703/4292, current 143.834869/4293: elapsed=17157.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.834869
last_received_ts = 143.834335
last_seq = 4293
current_ts = 143.852020
current_received_ts = 143.851517
current_seq = 4294
count = 78
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.834869/4293, current 143.852020/4294: elapsed=17156.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.852020
last_received_ts = 143.851517
last_seq = 4294
current_ts = 143.869186
current_received_ts = 143.868668
current_seq = 4295
count = 79
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.852020/4294, current 143.869186/4295: elapsed=17162.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.869186
last_received_ts = 143.868668
last_seq = 4295
current_ts = 143.886337
current_received_ts = 143.885941
current_seq = 4296
count = 80
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.869186/4295, current 143.886337/4296: elapsed=17159.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.886337
last_received_ts = 143.885941
last_seq = 4296
current_ts = 143.903488
current_received_ts = 143.903076
current_seq = 4297
count = 81
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.886337/4296, current 143.903488/4297: elapsed=17151.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.903488
last_received_ts = 143.903076
last_seq = 4297
current_ts = 143.920654
current_received_ts = 143.920166
current_seq = 4298
count = 82
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.903488/4297, current 143.920654/4298: elapsed=17166.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.920654
last_received_ts = 143.920166
last_seq = 4298
current_ts = 143.937820
current_received_ts = 143.937271
current_seq = 4299
count = 83
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.920654/4298, current 143.937820/4299: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.937820
last_received_ts = 143.937271
last_seq = 4299
current_ts = 143.954956
current_received_ts = 143.954453
current_seq = 4300
count = 84
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.937820/4299, current 143.954956/4300: elapsed=17148.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.954956
last_received_ts = 143.954453
last_seq = 4300
current_ts = 143.972122
current_received_ts = 143.971619
current_seq = 4301
count = 85
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.954956/4300, current 143.972122/4301: elapsed=17160.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.972122
last_received_ts = 143.971619
last_seq = 4301
current_ts = 143.989288
current_received_ts = 143.988785
current_seq = 4302
count = 86
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.972122/4301, current 143.989288/4302: elapsed=17159.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 143.989288
last_received_ts = 143.988785
last_seq = 4302
current_ts = 144.006439
current_received_ts = 144.005936
current_seq = 4303
count = 87
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 143.989288/4302, current 144.006439/4303: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.006439
last_received_ts = 144.005936
last_seq = 4303
current_ts = 144.023605
current_received_ts = 144.023209
current_seq = 4304
count = 88
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.006439/4303, current 144.023605/4304: elapsed=17166.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.023605
last_received_ts = 144.023209
last_seq = 4304
current_ts = 144.040756
current_received_ts = 144.040329
current_seq = 4305
count = 89
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.023605/4304, current 144.040756/4305: elapsed=17158.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.040756
last_received_ts = 144.040329
last_seq = 4305
current_ts = 144.057922
current_received_ts = 144.057419
current_seq = 4306
count = 90
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.040756/4305, current 144.057922/4306: elapsed=17164.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.057922
last_received_ts = 144.057419
last_seq = 4306
current_ts = 144.075089
current_received_ts = 144.074585
current_seq = 4307
count = 91
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.057922/4306, current 144.075089/4307: elapsed=17156.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.075089
last_received_ts = 144.074585
last_seq = 4307
current_ts = 144.092239
current_received_ts = 144.091736
current_seq = 4308
count = 92
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.075089/4307, current 144.092239/4308: elapsed=17161.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.092239
last_received_ts = 144.091736
last_seq = 4308
current_ts = 144.109390
current_received_ts = 144.108887
current_seq = 4309
count = 93
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.092239/4308, current 144.109390/4309: elapsed=17146.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.109390
last_received_ts = 144.108887
last_seq = 4309
current_ts = 144.126556
current_received_ts = 144.126083
current_seq = 4310
count = 94
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.109390/4309, current 144.126556/4310: elapsed=17171.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.126556
last_received_ts = 144.126083
last_seq = 4310
current_ts = 144.143723
current_received_ts = 144.143219
current_seq = 4311
count = 95
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.126556/4310, current 144.143723/4311: elapsed=17156.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.143723
last_received_ts = 144.143219
last_seq = 4311
current_ts = 144.160873
current_received_ts = 144.160339
current_seq = 4312
count = 96
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.143723/4311, current 144.160873/4312: elapsed=17155.0us expected=17229.0us +- 86.1us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.160873
last_received_ts = 144.160339
last_seq = 4312
current_ts = 144.178040
current_received_ts = 144.178116
current_seq = 4313
count = 97
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.160873/4312, current 144.178040/4313: elapsed=17173.0us expected=17229.0us +- 86.1us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 144.178040
last_received_ts = 144.178116
last_seq = 4313
current_ts = 144.195190
current_received_ts = 144.194595
current_seq = 4314
count = 98
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 144.178040/4313, current 144.195190/4314: elapsed=17139.0us expected=17229.0us +- 86.1us, error 0.5%
(kms_flip:5575) DEBUG: inconsistent flip ts/seq: last 144.178040/4313, current 144.195190/4314: elapsed=17139.0us expected=17229.0us
(kms_flip:5575) DEBUG: expected 5472, counted 98, encoder type 2
(kms_flip:5575) DEBUG: dropped frames, expected 5472, counted 98, encoder type 2
(kms_flip:5575) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:5575) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:5575) igt_core-INFO: Stack trace:
(kms_flip:5575) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:5575) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:5575) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:5575) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:5575) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:5575) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5575) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5575) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (6.492s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:5575) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:5575) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:5575) DEBUG: flip ts/seq: last 149.240524/4605, current 149.257416/4606: elapsed=16891.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.257416
last_received_ts = 149.256927
last_seq = 4606
current_ts = 149.274307
current_received_ts = 149.273727
current_seq = 4607
count = 9
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.257416/4606, current 149.274307/4607: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.274307
last_received_ts = 149.273727
last_seq = 4607
current_ts = 149.291214
current_received_ts = 149.290695
current_seq = 4608
count = 10
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.274307/4607, current 149.291214/4608: elapsed=16905.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.291214
last_received_ts = 149.290695
last_seq = 4608
current_ts = 149.308105
current_received_ts = 149.307587
current_seq = 4609
count = 11
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.291214/4608, current 149.308105/4609: elapsed=16893.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.308105
last_received_ts = 149.307587
last_seq = 4609
current_ts = 149.324997
current_received_ts = 149.324478
current_seq = 4610
count = 12
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.308105/4609, current 149.324997/4610: elapsed=16894.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.324997
last_received_ts = 149.324478
last_seq = 4610
current_ts = 149.341873
current_received_ts = 149.341370
current_seq = 4611
count = 13
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.324997/4610, current 149.341873/4611: elapsed=16880.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.341873
last_received_ts = 149.341370
last_seq = 4611
current_ts = 149.358780
current_received_ts = 149.358261
current_seq = 4612
count = 14
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.341873/4611, current 149.358780/4612: elapsed=16903.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.358780
last_received_ts = 149.358261
last_seq = 4612
current_ts = 149.375671
current_received_ts = 149.375153
current_seq = 4613
count = 15
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.358780/4612, current 149.375671/4613: elapsed=16894.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.375671
last_received_ts = 149.375153
last_seq = 4613
current_ts = 149.392563
current_received_ts = 149.392059
current_seq = 4614
count = 16
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.375671/4613, current 149.392563/4614: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.392563
last_received_ts = 149.392059
last_seq = 4614
current_ts = 149.409454
current_received_ts = 149.408936
current_seq = 4615
count = 17
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.392563/4614, current 149.409454/4615: elapsed=16879.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.409454
last_received_ts = 149.408936
last_seq = 4615
current_ts = 149.426346
current_received_ts = 149.425842
current_seq = 4616
count = 18
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.409454/4615, current 149.426346/4616: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.426346
last_received_ts = 149.425842
last_seq = 4616
current_ts = 149.443237
current_received_ts = 149.442734
current_seq = 4617
count = 19
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.426346/4616, current 149.443237/4617: elapsed=16903.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.443237
last_received_ts = 149.442734
last_seq = 4617
current_ts = 149.460129
current_received_ts = 149.459625
current_seq = 4618
count = 20
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.443237/4617, current 149.460129/4618: elapsed=16885.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.460129
last_received_ts = 149.459625
last_seq = 4618
current_ts = 149.477036
current_received_ts = 149.476517
current_seq = 4619
count = 21
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.460129/4618, current 149.477036/4619: elapsed=16903.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.477036
last_received_ts = 149.476517
last_seq = 4619
current_ts = 149.493927
current_received_ts = 149.493408
current_seq = 4620
count = 22
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.477036/4619, current 149.493927/4620: elapsed=16893.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.493927
last_received_ts = 149.493408
last_seq = 4620
current_ts = 149.510818
current_received_ts = 149.510300
current_seq = 4621
count = 23
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.493927/4620, current 149.510818/4621: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.510818
last_received_ts = 149.510300
last_seq = 4621
current_ts = 149.527710
current_received_ts = 149.527206
current_seq = 4622
count = 24
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.510818/4621, current 149.527710/4622: elapsed=16889.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.527710
last_received_ts = 149.527206
last_seq = 4622
current_ts = 149.544601
current_received_ts = 149.544083
current_seq = 4623
count = 25
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.527710/4622, current 149.544601/4623: elapsed=16896.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.544601
last_received_ts = 149.544083
last_seq = 4623
current_ts = 149.561478
current_received_ts = 149.560974
current_seq = 4624
count = 26
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.544601/4623, current 149.561478/4624: elapsed=16881.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.561478
last_received_ts = 149.560974
last_seq = 4624
current_ts = 149.578384
current_received_ts = 149.577866
current_seq = 4625
count = 27
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.561478/4624, current 149.578384/4625: elapsed=16896.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.578384
last_received_ts = 149.577866
last_seq = 4625
current_ts = 149.595276
current_received_ts = 149.594757
current_seq = 4626
count = 28
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.578384/4625, current 149.595276/4626: elapsed=16891.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.595276
last_received_ts = 149.594757
last_seq = 4626
current_ts = 149.612167
current_received_ts = 149.611649
current_seq = 4627
count = 29
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.595276/4626, current 149.612167/4627: elapsed=16903.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.612167
last_received_ts = 149.611649
last_seq = 4627
current_ts = 149.629059
current_received_ts = 149.628540
current_seq = 4628
count = 30
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.612167/4627, current 149.629059/4628: elapsed=16893.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.629059
last_received_ts = 149.628540
last_seq = 4628
current_ts = 149.645950
current_received_ts = 149.645432
current_seq = 4629
count = 31
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.629059/4628, current 149.645950/4629: elapsed=16878.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.645950
last_received_ts = 149.645432
last_seq = 4629
current_ts = 149.662842
current_received_ts = 149.662338
current_seq = 4630
count = 32
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.645950/4629, current 149.662842/4630: elapsed=16898.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.662842
last_received_ts = 149.662338
last_seq = 4630
current_ts = 149.679749
current_received_ts = 149.679214
current_seq = 4631
count = 33
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.662842/4630, current 149.679749/4631: elapsed=16901.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.679749
last_received_ts = 149.679214
last_seq = 4631
current_ts = 149.696625
current_received_ts = 149.696121
current_seq = 4632
count = 34
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.679749/4631, current 149.696625/4632: elapsed=16881.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.696625
last_received_ts = 149.696121
last_seq = 4632
current_ts = 149.713516
current_received_ts = 149.713013
current_seq = 4633
count = 35
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.696625/4632, current 149.713516/4633: elapsed=16891.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.713516
last_received_ts = 149.713013
last_seq = 4633
current_ts = 149.730408
current_received_ts = 149.729904
current_seq = 4634
count = 36
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.713516/4633, current 149.730408/4634: elapsed=16898.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.730408
last_received_ts = 149.729904
last_seq = 4634
current_ts = 149.747299
current_received_ts = 149.746796
current_seq = 4635
count = 37
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.730408/4634, current 149.747299/4635: elapsed=16887.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.747299
last_received_ts = 149.746796
last_seq = 4635
current_ts = 149.764191
current_received_ts = 149.763687
current_seq = 4636
count = 38
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.747299/4635, current 149.764191/4636: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.764191
last_received_ts = 149.763687
last_seq = 4636
current_ts = 149.781082
current_received_ts = 149.780579
current_seq = 4637
count = 39
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.764191/4636, current 149.781082/4637: elapsed=16893.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.781082
last_received_ts = 149.780579
last_seq = 4637
current_ts = 149.797989
current_received_ts = 149.797470
current_seq = 4638
count = 40
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.781082/4637, current 149.797989/4638: elapsed=16905.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.797989
last_received_ts = 149.797470
last_seq = 4638
current_ts = 149.814865
current_received_ts = 149.814362
current_seq = 4639
count = 41
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.797989/4638, current 149.814865/4639: elapsed=16883.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.814865
last_received_ts = 149.814362
last_seq = 4639
current_ts = 149.831757
current_received_ts = 149.831253
current_seq = 4640
count = 42
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.814865/4639, current 149.831757/4640: elapsed=16889.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.831757
last_received_ts = 149.831253
last_seq = 4640
current_ts = 149.848663
current_received_ts = 149.848145
current_seq = 4641
count = 43
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.831757/4640, current 149.848663/4641: elapsed=16905.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.848663
last_received_ts = 149.848145
last_seq = 4641
current_ts = 149.865555
current_received_ts = 149.865051
current_seq = 4642
count = 44
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.848663/4641, current 149.865555/4642: elapsed=16883.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.865555
last_received_ts = 149.865051
last_seq = 4642
current_ts = 149.882446
current_received_ts = 149.881927
current_seq = 4643
count = 45
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.865555/4642, current 149.882446/4643: elapsed=16890.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.882446
last_received_ts = 149.881927
last_seq = 4643
current_ts = 149.899338
current_received_ts = 149.898819
current_seq = 4644
count = 46
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.882446/4643, current 149.899338/4644: elapsed=16906.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.899338
last_received_ts = 149.898819
last_seq = 4644
current_ts = 149.916229
current_received_ts = 149.915726
current_seq = 4645
count = 47
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.899338/4644, current 149.916229/4645: elapsed=16885.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.916229
last_received_ts = 149.915726
last_seq = 4645
current_ts = 149.933136
current_received_ts = 149.932602
current_seq = 4646
count = 48
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.916229/4645, current 149.933136/4646: elapsed=16900.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.933136
last_received_ts = 149.932602
last_seq = 4646
current_ts = 149.950012
current_received_ts = 149.949509
current_seq = 4647
count = 49
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.933136/4646, current 149.950012/4647: elapsed=16881.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.950012
last_received_ts = 149.949509
last_seq = 4647
current_ts = 149.966919
current_received_ts = 149.966400
current_seq = 4648
count = 50
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.950012/4647, current 149.966919/4648: elapsed=16902.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.966919
last_received_ts = 149.966400
last_seq = 4648
current_ts = 149.983795
current_received_ts = 149.983307
current_seq = 4649
count = 51
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.966919/4648, current 149.983795/4649: elapsed=16881.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 149.983795
last_received_ts = 149.983307
last_seq = 4649
current_ts = 150.000702
current_received_ts = 150.000214
current_seq = 4650
count = 52
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 149.983795/4649, current 150.000702/4650: elapsed=16905.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.000702
last_received_ts = 150.000214
last_seq = 4650
current_ts = 150.017593
current_received_ts = 150.017090
current_seq = 4651
count = 53
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.000702/4650, current 150.017593/4651: elapsed=16891.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.017593
last_received_ts = 150.017090
last_seq = 4651
current_ts = 150.034485
current_received_ts = 150.033966
current_seq = 4652
count = 54
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.017593/4651, current 150.034485/4652: elapsed=16888.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.034485
last_received_ts = 150.033966
last_seq = 4652
current_ts = 150.051376
current_received_ts = 150.050858
current_seq = 4653
count = 55
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.034485/4652, current 150.051376/4653: elapsed=16899.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.051376
last_received_ts = 150.050858
last_seq = 4653
current_ts = 150.068268
current_received_ts = 150.067764
current_seq = 4654
count = 56
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.051376/4653, current 150.068268/4654: elapsed=16888.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.068268
last_received_ts = 150.067764
last_seq = 4654
current_ts = 150.085159
current_received_ts = 150.084641
current_seq = 4655
count = 57
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.068268/4654, current 150.085159/4655: elapsed=16887.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.085159
last_received_ts = 150.084641
last_seq = 4655
current_ts = 150.102051
current_received_ts = 150.101547
current_seq = 4656
count = 58
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.085159/4655, current 150.102051/4656: elapsed=16895.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.102051
last_received_ts = 150.101547
last_seq = 4656
current_ts = 150.118942
current_received_ts = 150.118423
current_seq = 4657
count = 59
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.102051/4656, current 150.118942/4657: elapsed=16900.0us expected=16923.5us +- 84.6us, error 0.1%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.118942
last_received_ts = 150.118423
last_seq = 4657
current_ts = 150.135834
current_received_ts = 150.135330
current_seq = 4658
count = 60
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.118942/4657, current 150.135834/4658: elapsed=16883.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.135834
last_received_ts = 150.135330
last_seq = 4658
current_ts = 150.152725
current_received_ts = 150.152222
current_seq = 4659
count = 61
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.135834/4658, current 150.152725/4659: elapsed=16890.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.152725
last_received_ts = 150.152222
last_seq = 4659
current_ts = 150.169617
current_received_ts = 150.169113
current_seq = 4660
count = 62
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.152725/4659, current 150.169617/4660: elapsed=16894.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.169617
last_received_ts = 150.169113
last_seq = 4660
current_ts = 150.186508
current_received_ts = 150.186005
current_seq = 4661
count = 63
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.169617/4660, current 150.186508/4661: elapsed=16894.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.186508
last_received_ts = 150.186005
last_seq = 4661
current_ts = 150.203400
current_received_ts = 150.202911
current_seq = 4662
count = 64
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.186508/4661, current 150.203400/4662: elapsed=16892.0us expected=16923.5us +- 84.6us, error 0.2%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.203400
last_received_ts = 150.202911
last_seq = 4662
current_ts = 150.220276
current_received_ts = 150.219788
current_seq = 4663
count = 65
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.203400/4662, current 150.220276/4663: elapsed=16879.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.220276
last_received_ts = 150.219788
last_seq = 4663
current_ts = 150.237137
current_received_ts = 150.236633
current_seq = 4664
count = 66
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.220276/4663, current 150.237137/4664: elapsed=16853.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.237137
last_received_ts = 150.236633
last_seq = 4664
current_ts = 150.253998
current_received_ts = 150.253494
current_seq = 4665
count = 67
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.237137/4664, current 150.253998/4665: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.253998
last_received_ts = 150.253494
last_seq = 4665
current_ts = 150.270859
current_received_ts = 150.270462
current_seq = 4666
count = 68
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.253998/4665, current 150.270859/4666: elapsed=16864.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.270859
last_received_ts = 150.270462
last_seq = 4666
current_ts = 150.287720
current_received_ts = 150.287323
current_seq = 4667
count = 69
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.270859/4666, current 150.287720/4667: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.287720
last_received_ts = 150.287323
last_seq = 4667
current_ts = 150.304611
current_received_ts = 150.304214
current_seq = 4668
count = 70
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.287720/4667, current 150.304611/4668: elapsed=16877.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.304611
last_received_ts = 150.304214
last_seq = 4668
current_ts = 150.321457
current_received_ts = 150.321121
current_seq = 4669
count = 71
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.304611/4668, current 150.321457/4669: elapsed=16853.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.321457
last_received_ts = 150.321121
last_seq = 4669
current_ts = 150.338318
current_received_ts = 150.337936
current_seq = 4670
count = 72
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.321457/4669, current 150.338318/4670: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.338318
last_received_ts = 150.337936
last_seq = 4670
current_ts = 150.355194
current_received_ts = 150.354736
current_seq = 4671
count = 73
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.338318/4670, current 150.355194/4671: elapsed=16868.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.355194
last_received_ts = 150.354736
last_seq = 4671
current_ts = 150.372055
current_received_ts = 150.371552
current_seq = 4672
count = 74
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.355194/4671, current 150.372055/4672: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.372055
last_received_ts = 150.371552
last_seq = 4672
current_ts = 150.388931
current_received_ts = 150.388519
current_seq = 4673
count = 75
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.372055/4672, current 150.388931/4673: elapsed=16876.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.388931
last_received_ts = 150.388519
last_seq = 4673
current_ts = 150.405792
current_received_ts = 150.405228
current_seq = 4674
count = 76
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.388931/4673, current 150.405792/4674: elapsed=16855.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.405792
last_received_ts = 150.405228
last_seq = 4674
current_ts = 150.422668
current_received_ts = 150.422150
current_seq = 4675
count = 77
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.405792/4674, current 150.422668/4675: elapsed=16876.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.422668
last_received_ts = 150.422150
last_seq = 4675
current_ts = 150.439529
current_received_ts = 150.439011
current_seq = 4676
count = 78
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.422668/4675, current 150.439529/4676: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.439529
last_received_ts = 150.439011
last_seq = 4676
current_ts = 150.456390
current_received_ts = 150.455887
current_seq = 4677
count = 79
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.439529/4676, current 150.456390/4677: elapsed=16855.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.456390
last_received_ts = 150.455887
last_seq = 4677
current_ts = 150.473251
current_received_ts = 150.472748
current_seq = 4678
count = 80
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.456390/4677, current 150.473251/4678: elapsed=16862.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.473251
last_received_ts = 150.472748
last_seq = 4678
current_ts = 150.490128
current_received_ts = 150.489609
current_seq = 4679
count = 81
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.473251/4678, current 150.490128/4679: elapsed=16879.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.490128
last_received_ts = 150.489609
last_seq = 4679
current_ts = 150.506973
current_received_ts = 150.506470
current_seq = 4680
count = 82
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.490128/4679, current 150.506973/4680: elapsed=16853.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.506973
last_received_ts = 150.506470
last_seq = 4680
current_ts = 150.523849
current_received_ts = 150.523331
current_seq = 4681
count = 83
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.506973/4680, current 150.523849/4681: elapsed=16876.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.523849
last_received_ts = 150.523331
last_seq = 4681
current_ts = 150.540710
current_received_ts = 150.540207
current_seq = 4682
count = 84
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.523849/4681, current 150.540710/4682: elapsed=16857.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.540710
last_received_ts = 150.540207
last_seq = 4682
current_ts = 150.557587
current_received_ts = 150.557083
current_seq = 4683
count = 85
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.540710/4682, current 150.557587/4683: elapsed=16875.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.557587
last_received_ts = 150.557083
last_seq = 4683
current_ts = 150.574448
current_received_ts = 150.573944
current_seq = 4684
count = 86
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.557587/4683, current 150.574448/4684: elapsed=16858.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.574448
last_received_ts = 150.573944
last_seq = 4684
current_ts = 150.591324
current_received_ts = 150.590805
current_seq = 4685
count = 87
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.574448/4684, current 150.591324/4685: elapsed=16874.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.591324
last_received_ts = 150.590805
last_seq = 4685
current_ts = 150.608170
current_received_ts = 150.607635
current_seq = 4686
count = 88
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.591324/4685, current 150.608170/4686: elapsed=16852.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.608170
last_received_ts = 150.607635
last_seq = 4686
current_ts = 150.625046
current_received_ts = 150.624527
current_seq = 4687
count = 89
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.608170/4686, current 150.625046/4687: elapsed=16877.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.625046
last_received_ts = 150.624527
last_seq = 4687
current_ts = 150.641907
current_received_ts = 150.641403
current_seq = 4688
count = 90
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.625046/4687, current 150.641907/4688: elapsed=16859.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.641907
last_received_ts = 150.641403
last_seq = 4688
current_ts = 150.658783
current_received_ts = 150.658264
current_seq = 4689
count = 91
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.641907/4688, current 150.658783/4689: elapsed=16873.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.658783
last_received_ts = 150.658264
last_seq = 4689
current_ts = 150.675629
current_received_ts = 150.675125
current_seq = 4690
count = 92
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.658783/4689, current 150.675629/4690: elapsed=16855.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.675629
last_received_ts = 150.675125
last_seq = 4690
current_ts = 150.692505
current_received_ts = 150.692001
current_seq = 4691
count = 93
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.675629/4690, current 150.692505/4691: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.692505
last_received_ts = 150.692001
last_seq = 4691
current_ts = 150.709366
current_received_ts = 150.708862
current_seq = 4692
count = 94
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.692505/4691, current 150.709366/4692: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.709366
last_received_ts = 150.708862
last_seq = 4692
current_ts = 150.726242
current_received_ts = 150.725723
current_seq = 4693
count = 95
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.709366/4692, current 150.726242/4693: elapsed=16876.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.726242
last_received_ts = 150.725723
last_seq = 4693
current_ts = 150.743103
current_received_ts = 150.742584
current_seq = 4694
count = 96
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.726242/4693, current 150.743103/4694: elapsed=16856.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.743103
last_received_ts = 150.742584
last_seq = 4694
current_ts = 150.759964
current_received_ts = 150.759460
current_seq = 4695
count = 97
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.743103/4694, current 150.759964/4695: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.759964
last_received_ts = 150.759460
last_seq = 4695
current_ts = 150.776825
current_received_ts = 150.776337
current_seq = 4696
count = 98
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.759964/4695, current 150.776825/4696: elapsed=16869.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.776825
last_received_ts = 150.776337
last_seq = 4696
current_ts = 150.793686
current_received_ts = 150.793182
current_seq = 4697
count = 99
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.776825/4696, current 150.793686/4697: elapsed=16863.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.793686
last_received_ts = 150.793182
last_seq = 4697
current_ts = 150.810562
current_received_ts = 150.810059
current_seq = 4698
count = 100
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.793686/4697, current 150.810562/4698: elapsed=16863.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.810562
last_received_ts = 150.810059
last_seq = 4698
current_ts = 150.827438
current_received_ts = 150.826920
current_seq = 4699
count = 101
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.810562/4698, current 150.827438/4699: elapsed=16879.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.827438
last_received_ts = 150.826920
last_seq = 4699
current_ts = 150.844284
current_received_ts = 150.843781
current_seq = 4700
count = 102
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.827438/4699, current 150.844284/4700: elapsed=16853.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.844284
last_received_ts = 150.843781
last_seq = 4700
current_ts = 150.861145
current_received_ts = 150.860657
current_seq = 4701
count = 103
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.844284/4700, current 150.861145/4701: elapsed=16863.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.861145
last_received_ts = 150.860657
last_seq = 4701
current_ts = 150.878036
current_received_ts = 150.877518
current_seq = 4702
count = 104
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.861145/4701, current 150.878036/4702: elapsed=16878.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.878036
last_received_ts = 150.877518
last_seq = 4702
current_ts = 150.894897
current_received_ts = 150.894379
current_seq = 4703
count = 105
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.878036/4702, current 150.894897/4703: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.894897
last_received_ts = 150.894379
last_seq = 4703
current_ts = 150.911743
current_received_ts = 150.911240
current_seq = 4704
count = 106
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.894897/4703, current 150.911743/4704: elapsed=16853.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.911743
last_received_ts = 150.911240
last_seq = 4704
current_ts = 150.928619
current_received_ts = 150.928101
current_seq = 4705
count = 107
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.911743/4704, current 150.928619/4705: elapsed=16879.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.928619
last_received_ts = 150.928101
last_seq = 4705
current_ts = 150.945496
current_received_ts = 150.944977
current_seq = 4706
count = 108
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.928619/4705, current 150.945496/4706: elapsed=16864.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.945496
last_received_ts = 150.944977
last_seq = 4706
current_ts = 150.962341
current_received_ts = 150.961868
current_seq = 4707
count = 109
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.945496/4706, current 150.962341/4707: elapsed=16856.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.962341
last_received_ts = 150.961868
last_seq = 4707
current_ts = 150.979218
current_received_ts = 150.978714
current_seq = 4708
count = 110
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.962341/4707, current 150.979218/4708: elapsed=16867.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.979218
last_received_ts = 150.978714
last_seq = 4708
current_ts = 150.996078
current_received_ts = 150.995667
current_seq = 4709
count = 111
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.979218/4708, current 150.996078/4709: elapsed=16863.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 150.996078
last_received_ts = 150.995667
last_seq = 4709
current_ts = 151.012939
current_received_ts = 151.012512
current_seq = 4710
count = 112
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 150.996078/4709, current 151.012939/4710: elapsed=16868.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.012939
last_received_ts = 151.012512
last_seq = 4710
current_ts = 151.029816
current_received_ts = 151.029221
current_seq = 4711
count = 113
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.012939/4710, current 151.029816/4711: elapsed=16871.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.029816
last_received_ts = 151.029221
last_seq = 4711
current_ts = 151.046677
current_received_ts = 151.046082
current_seq = 4712
count = 114
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.029816/4711, current 151.046677/4712: elapsed=16858.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.046677
last_received_ts = 151.046082
last_seq = 4712
current_ts = 151.063538
current_received_ts = 151.063049
current_seq = 4713
count = 115
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.046677/4712, current 151.063538/4713: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.063538
last_received_ts = 151.063049
last_seq = 4713
current_ts = 151.080414
current_received_ts = 151.079895
current_seq = 4714
count = 116
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.063538/4713, current 151.080414/4714: elapsed=16875.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.080414
last_received_ts = 151.079895
last_seq = 4714
current_ts = 151.097275
current_received_ts = 151.096756
current_seq = 4715
count = 117
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.080414/4714, current 151.097275/4715: elapsed=16865.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.097275
last_received_ts = 151.096756
last_seq = 4715
current_ts = 151.114151
current_received_ts = 151.113617
current_seq = 4716
count = 118
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.097275/4715, current 151.114151/4716: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.114151
last_received_ts = 151.113617
last_seq = 4716
current_ts = 151.130997
current_received_ts = 151.130493
current_seq = 4717
count = 119
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.114151/4716, current 151.130997/4717: elapsed=16855.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.130997
last_received_ts = 151.130493
last_seq = 4717
current_ts = 151.147873
current_received_ts = 151.147369
current_seq = 4718
count = 120
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.130997/4717, current 151.147873/4718: elapsed=16868.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.147873
last_received_ts = 151.147369
last_seq = 4718
current_ts = 151.164734
current_received_ts = 151.164230
current_seq = 4719
count = 121
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.147873/4718, current 151.164734/4719: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.164734
last_received_ts = 151.164230
last_seq = 4719
current_ts = 151.181610
current_received_ts = 151.181091
current_seq = 4720
count = 122
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.164734/4719, current 151.181610/4720: elapsed=16873.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.181610
last_received_ts = 151.181091
last_seq = 4720
current_ts = 151.198471
current_received_ts = 151.197952
current_seq = 4721
count = 123
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.181610/4720, current 151.198471/4721: elapsed=16866.0us expected=16923.5us +- 84.6us, error 0.3%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.198471
last_received_ts = 151.197952
last_seq = 4721
current_ts = 151.215317
current_received_ts = 151.214828
current_seq = 4722
count = 124
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.198471/4721, current 151.215317/4722: elapsed=16850.0us expected=16923.5us +- 84.6us, error 0.4%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.215317
last_received_ts = 151.214828
last_seq = 4722
current_ts = 151.232162
current_received_ts = 151.231644
current_seq = 4723
count = 125
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.215317/4722, current 151.232162/4723: elapsed=16841.0us expected=16923.5us +- 84.6us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.232162
last_received_ts = 151.231644
last_seq = 4723
current_ts = 151.249008
current_received_ts = 151.248489
current_seq = 4724
count = 126
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.232162/4723, current 151.249008/4724: elapsed=16842.0us expected=16923.5us +- 84.6us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.249008
last_received_ts = 151.248489
last_seq = 4724
current_ts = 151.265854
current_received_ts = 151.265335
current_seq = 4725
count = 127
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.249008/4724, current 151.265854/4725: elapsed=16842.0us expected=16923.5us +- 84.6us, error 0.5%
(kms_flip:5575) DEBUG: name = flip
last_ts = 151.265854
last_received_ts = 151.265335
last_seq = 4725
current_ts = 151.282684
current_received_ts = 151.282181
current_seq = 4726
count = 128
seq_step = 1
(kms_flip:5575) DEBUG: flip ts/seq: last 151.265854/4725, current 151.282684/4726: elapsed=16837.0us expected=16923.5us +- 84.6us, error 0.5%
(kms_flip:5575) DEBUG: inconsistent flip ts/seq: last 151.265854/4725, current 151.282684/4726: elapsed=16837.0us expected=16923.5us
(kms_flip:5575) DEBUG: expected 5571, counted 128, encoder type 2
(kms_flip:5575) DEBUG: dropped frames, expected 5571, counted 128, encoder type 2
(kms_flip:5575) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:5575) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:5575) igt_core-INFO: Stack trace:
(kms_flip:5575) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:5575) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:5575) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:5575) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:5575) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:5575) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5575) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5575) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (7.346s)
Starting dynamic subtest: AD-DP2-HDMI-A3
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.659s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.674s)
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.650s)
Subtest 2x-plain-flip-ts-check: FAIL (36.514s)