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

shard-bmg-2

IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc5-xe x86_64)

Using IGT_SRANDOM=1730320221 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: 2x-plain-flip-ts-check-interruptible
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 17026.8us +- 5.868us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 17027us +- 5.868us, difference 360.1us (61.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2121 __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 (5.111s)
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 16856.8us +- 2.949us accuracy 0.05%
vblank interval differs from modeline! expected 16666.7us, measured 16857us +- 2.949us, difference 190.1us (64.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2121 __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 (6.936s)
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 16747.0us +- 6.880us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16747us +- 6.880us, difference 80.3us (11.7 sigma)
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.629s)
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 16707.4us +- 5.020us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16707us +- 5.020us, difference 40.8us (8.1 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.644s)
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 16692.3us +- 4.377us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16692us +- 4.377us, difference 25.6us (5.9 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.613s)
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 16674.7us +- 3.219us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16675us +- 3.219us, difference 8.0us (2.5 sigma)
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.629s)
Subtest 2x-plain-flip-ts-check-interruptible: FAIL (34.602s)

Starting subtest: 2x-plain-flip-ts-check-interruptible
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:3996) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3996) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3996) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3996) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3996) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3996) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3996) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3996) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3996) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3996) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cb72160, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cb72160, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cb7fb60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cb7fb60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cba5bd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cba5bd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cbb7290, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) intel_allocator_simple-DEBUG: <ial: 0x55883cbb7290, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3996) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3996) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:3996) DEBUG: No stale events found
(kms_flip:3996) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3996) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3996) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3996) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3996) INFO: Expected frametime: 16667us; measured 17026.8us +- 5.868us accuracy 0.10%
(kms_flip:3996) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17027us +- 5.868us, difference 360.1us (61.4 sigma)
(kms_flip:3996) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 254.373581
current_received_ts = 254.373230
current_seq = 8233
count = 0
seq_step = 1
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.373581
last_received_ts = 254.373230
last_seq = 8233
current_ts = 254.390610
current_received_ts = 254.390228
current_seq = 8234
count = 1
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.373581/8233, current 254.390610/8234: elapsed=17024.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.390610
last_received_ts = 254.390228
last_seq = 8234
current_ts = 254.407639
current_received_ts = 254.407242
current_seq = 8235
count = 2
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.390610/8234, current 254.407639/8235: elapsed=17032.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.407639
last_received_ts = 254.407242
last_seq = 8235
current_ts = 254.424667
current_received_ts = 254.424255
current_seq = 8236
count = 3
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.407639/8235, current 254.424667/8236: elapsed=17023.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.424667
last_received_ts = 254.424255
last_seq = 8236
current_ts = 254.441696
current_received_ts = 254.441315
current_seq = 8237
count = 4
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.424667/8236, current 254.441696/8237: elapsed=17026.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.441696
last_received_ts = 254.441315
last_seq = 8237
current_ts = 254.458725
current_received_ts = 254.458344
current_seq = 8238
count = 5
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.441696/8237, current 254.458725/8238: elapsed=17032.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.458725
last_received_ts = 254.458344
last_seq = 8238
current_ts = 254.475754
current_received_ts = 254.475372
current_seq = 8239
count = 6
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.458725/8238, current 254.475754/8239: elapsed=17025.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.475754
last_received_ts = 254.475372
last_seq = 8239
current_ts = 254.492767
current_received_ts = 254.492325
current_seq = 8240
count = 7
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.475754/8239, current 254.492767/8240: elapsed=17027.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.492767
last_received_ts = 254.492325
last_seq = 8240
current_ts = 254.509811
current_received_ts = 254.509430
current_seq = 8241
count = 8
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.492767/8240, current 254.509811/8241: elapsed=17031.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.509811
last_received_ts = 254.509430
last_seq = 8241
current_ts = 254.526825
current_received_ts = 254.526459
current_seq = 8242
count = 9
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.509811/8241, current 254.526825/8242: elapsed=17024.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.526825
last_received_ts = 254.526459
last_seq = 8242
current_ts = 254.543869
current_received_ts = 254.543488
current_seq = 8243
count = 10
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.526825/8242, current 254.543869/8243: elapsed=17033.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.543869
last_received_ts = 254.543488
last_seq = 8243
current_ts = 254.560883
current_received_ts = 254.560410
current_seq = 8244
count = 11
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.543869/8243, current 254.560883/8244: elapsed=17023.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.560883
last_received_ts = 254.560410
last_seq = 8244
current_ts = 254.577911
current_received_ts = 254.577530
current_seq = 8245
count = 12
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.560883/8244, current 254.577911/8245: elapsed=17026.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.577911
last_received_ts = 254.577530
last_seq = 8245
current_ts = 254.594940
current_received_ts = 254.594559
current_seq = 8246
count = 13
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.577911/8245, current 254.594940/8246: elapsed=17029.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.594940
last_received_ts = 254.594559
last_seq = 8246
current_ts = 254.611969
current_received_ts = 254.611588
current_seq = 8247
count = 14
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.594940/8246, current 254.611969/8247: elapsed=17026.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.611969
last_received_ts = 254.611588
last_seq = 8247
current_ts = 254.628983
current_received_ts = 254.628571
current_seq = 8248
count = 15
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.611969/8247, current 254.628983/8248: elapsed=17024.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.628983
last_received_ts = 254.628571
last_seq = 8248
current_ts = 254.646027
current_received_ts = 254.645645
current_seq = 8249
count = 16
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.628983/8248, current 254.646027/8249: elapsed=17032.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.646027
last_received_ts = 254.645645
last_seq = 8249
current_ts = 254.663055
current_received_ts = 254.662689
current_seq = 8250
count = 17
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.646027/8249, current 254.663055/8250: elapsed=17034.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.663055
last_received_ts = 254.662689
last_seq = 8250
current_ts = 254.680084
current_received_ts = 254.679703
current_seq = 8251
count = 18
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.663055/8250, current 254.680084/8251: elapsed=17023.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.680084
last_received_ts = 254.679703
last_seq = 8251
current_ts = 254.697113
current_received_ts = 254.696732
current_seq = 8252
count = 19
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.680084/8251, current 254.697113/8252: elapsed=17027.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.697113
last_received_ts = 254.696732
last_seq = 8252
current_ts = 254.714142
current_received_ts = 254.713760
current_seq = 8253
count = 20
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.697113/8252, current 254.714142/8253: elapsed=17030.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.714142
last_received_ts = 254.713760
last_seq = 8253
current_ts = 254.731155
current_received_ts = 254.730774
current_seq = 8254
count = 21
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.714142/8253, current 254.731155/8254: elapsed=17024.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.731155
last_received_ts = 254.730774
last_seq = 8254
current_ts = 254.748184
current_received_ts = 254.747803
current_seq = 8255
count = 22
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.731155/8254, current 254.748184/8255: elapsed=17028.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.748184
last_received_ts = 254.747803
last_seq = 8255
current_ts = 254.765213
current_received_ts = 254.764832
current_seq = 8256
count = 23
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.748184/8255, current 254.765213/8256: elapsed=17027.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.765213
last_received_ts = 254.764832
last_seq = 8256
current_ts = 254.782242
current_received_ts = 254.781708
current_seq = 8257
count = 24
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.765213/8256, current 254.782242/8257: elapsed=17022.0us expected=17026.8us +- 85.1us, error 0.0%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.782242
last_received_ts = 254.781708
last_seq = 8257
current_ts = 254.799240
current_received_ts = 254.798859
current_seq = 8258
count = 25
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.782242/8257, current 254.799240/8258: elapsed=17002.0us expected=17026.8us +- 85.1us, error 0.1%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.799240
last_received_ts = 254.798859
last_seq = 8258
current_ts = 254.816223
current_received_ts = 254.815689
current_seq = 8259
count = 26
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.799240/8258, current 254.816223/8259: elapsed=16983.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.816223
last_received_ts = 254.815689
last_seq = 8259
current_ts = 254.833206
current_received_ts = 254.832825
current_seq = 8260
count = 27
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.816223/8259, current 254.833206/8260: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.833206
last_received_ts = 254.832825
last_seq = 8260
current_ts = 254.850189
current_received_ts = 254.849655
current_seq = 8261
count = 28
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.833206/8260, current 254.850189/8261: elapsed=16987.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.850189
last_received_ts = 254.849655
last_seq = 8261
current_ts = 254.867172
current_received_ts = 254.866791
current_seq = 8262
count = 29
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.850189/8261, current 254.867172/8262: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.867172
last_received_ts = 254.866791
last_seq = 8262
current_ts = 254.884155
current_received_ts = 254.883728
current_seq = 8263
count = 30
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.867172/8262, current 254.884155/8263: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.884155
last_received_ts = 254.883728
last_seq = 8263
current_ts = 254.901138
current_received_ts = 254.900772
current_seq = 8264
count = 31
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.884155/8263, current 254.901138/8264: elapsed=16984.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.901138
last_received_ts = 254.900772
last_seq = 8264
current_ts = 254.918106
current_received_ts = 254.917679
current_seq = 8265
count = 32
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.901138/8264, current 254.918106/8265: elapsed=16972.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.918106
last_received_ts = 254.917679
last_seq = 8265
current_ts = 254.935104
current_received_ts = 254.934723
current_seq = 8266
count = 33
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.918106/8265, current 254.935104/8266: elapsed=16991.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.935104
last_received_ts = 254.934723
last_seq = 8266
current_ts = 254.952087
current_received_ts = 254.951691
current_seq = 8267
count = 34
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.935104/8266, current 254.952087/8267: elapsed=16990.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.952087
last_received_ts = 254.951691
last_seq = 8267
current_ts = 254.969070
current_received_ts = 254.968689
current_seq = 8268
count = 35
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.952087/8267, current 254.969070/8268: elapsed=16977.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.969070
last_received_ts = 254.968689
last_seq = 8268
current_ts = 254.986053
current_received_ts = 254.985657
current_seq = 8269
count = 36
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.969070/8268, current 254.986053/8269: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 254.986053
last_received_ts = 254.985657
last_seq = 8269
current_ts = 255.003036
current_received_ts = 255.002655
current_seq = 8270
count = 37
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 254.986053/8269, current 255.003036/8270: elapsed=16977.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.003036
last_received_ts = 255.002655
last_seq = 8270
current_ts = 255.020020
current_received_ts = 255.019684
current_seq = 8271
count = 38
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.003036/8270, current 255.020020/8271: elapsed=16982.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.020020
last_received_ts = 255.019684
last_seq = 8271
current_ts = 255.037003
current_received_ts = 255.036636
current_seq = 8272
count = 39
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.020020/8271, current 255.037003/8272: elapsed=16982.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.037003
last_received_ts = 255.036636
last_seq = 8272
current_ts = 255.053986
current_received_ts = 255.053619
current_seq = 8273
count = 40
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.037003/8272, current 255.053986/8273: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.053986
last_received_ts = 255.053619
last_seq = 8273
current_ts = 255.070969
current_received_ts = 255.070602
current_seq = 8274
count = 41
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.053986/8273, current 255.070969/8274: elapsed=16986.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.070969
last_received_ts = 255.070602
last_seq = 8274
current_ts = 255.087952
current_received_ts = 255.087616
current_seq = 8275
count = 42
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.070969/8274, current 255.087952/8275: elapsed=16980.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.087952
last_received_ts = 255.087616
last_seq = 8275
current_ts = 255.104935
current_received_ts = 255.104523
current_seq = 8276
count = 43
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.087952/8275, current 255.104935/8276: elapsed=16978.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.104935
last_received_ts = 255.104523
last_seq = 8276
current_ts = 255.121918
current_received_ts = 255.121582
current_seq = 8277
count = 44
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.104935/8276, current 255.121918/8277: elapsed=16987.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.121918
last_received_ts = 255.121582
last_seq = 8277
current_ts = 255.138916
current_received_ts = 255.138535
current_seq = 8278
count = 45
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.121918/8277, current 255.138916/8278: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.138916
last_received_ts = 255.138535
last_seq = 8278
current_ts = 255.155884
current_received_ts = 255.155518
current_seq = 8279
count = 46
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.138916/8278, current 255.155884/8279: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.155884
last_received_ts = 255.155518
last_seq = 8279
current_ts = 255.172867
current_received_ts = 255.172470
current_seq = 8280
count = 47
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.155884/8279, current 255.172867/8280: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.172867
last_received_ts = 255.172470
last_seq = 8280
current_ts = 255.189850
current_received_ts = 255.189484
current_seq = 8281
count = 48
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.172867/8280, current 255.189850/8281: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.189850
last_received_ts = 255.189484
last_seq = 8281
current_ts = 255.206848
current_received_ts = 255.206467
current_seq = 8282
count = 49
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.189850/8281, current 255.206848/8282: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.206848
last_received_ts = 255.206467
last_seq = 8282
current_ts = 255.223831
current_received_ts = 255.223450
current_seq = 8283
count = 50
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.206848/8282, current 255.223831/8283: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.223831
last_received_ts = 255.223450
last_seq = 8283
current_ts = 255.240814
current_received_ts = 255.240311
current_seq = 8284
count = 51
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.223831/8283, current 255.240814/8284: elapsed=16982.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.240814
last_received_ts = 255.240311
last_seq = 8284
current_ts = 255.257797
current_received_ts = 255.257416
current_seq = 8285
count = 52
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.240814/8284, current 255.257797/8285: elapsed=16980.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.257797
last_received_ts = 255.257416
last_seq = 8285
current_ts = 255.274780
current_received_ts = 255.274399
current_seq = 8286
count = 53
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.257797/8285, current 255.274780/8286: elapsed=16987.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.274780
last_received_ts = 255.274399
last_seq = 8286
current_ts = 255.291763
current_received_ts = 255.291382
current_seq = 8287
count = 54
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.274780/8286, current 255.291763/8287: elapsed=16986.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.291763
last_received_ts = 255.291382
last_seq = 8287
current_ts = 255.308746
current_received_ts = 255.308304
current_seq = 8288
count = 55
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.291763/8287, current 255.308746/8288: elapsed=16984.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.308746
last_received_ts = 255.308304
last_seq = 8288
current_ts = 255.325729
current_received_ts = 255.325363
current_seq = 8289
count = 56
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.308746/8288, current 255.325729/8289: elapsed=16986.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.325729
last_received_ts = 255.325363
last_seq = 8289
current_ts = 255.342712
current_received_ts = 255.342331
current_seq = 8290
count = 57
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.325729/8289, current 255.342712/8290: elapsed=16978.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.342712
last_received_ts = 255.342331
last_seq = 8290
current_ts = 255.359695
current_received_ts = 255.359314
current_seq = 8291
count = 58
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.342712/8290, current 255.359695/8291: elapsed=16984.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.359695
last_received_ts = 255.359314
last_seq = 8291
current_ts = 255.376678
current_received_ts = 255.376221
current_seq = 8292
count = 59
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.359695/8291, current 255.376678/8292: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.376678
last_received_ts = 255.376221
last_seq = 8292
current_ts = 255.393661
current_received_ts = 255.393280
current_seq = 8293
count = 60
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.376678/8292, current 255.393661/8293: elapsed=16982.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.393661
last_received_ts = 255.393280
last_seq = 8293
current_ts = 255.410645
current_received_ts = 255.410278
current_seq = 8294
count = 61
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.393661/8293, current 255.410645/8294: elapsed=16988.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.410645
last_received_ts = 255.410278
last_seq = 8294
current_ts = 255.427628
current_received_ts = 255.427261
current_seq = 8295
count = 62
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.410645/8294, current 255.427628/8295: elapsed=16980.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.427628
last_received_ts = 255.427261
last_seq = 8295
current_ts = 255.444626
current_received_ts = 255.444122
current_seq = 8296
count = 63
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.427628/8295, current 255.444626/8296: elapsed=16987.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.444626
last_received_ts = 255.444122
last_seq = 8296
current_ts = 255.461594
current_received_ts = 255.461212
current_seq = 8297
count = 64
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.444626/8296, current 255.461594/8297: elapsed=16977.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.461594
last_received_ts = 255.461212
last_seq = 8297
current_ts = 255.478577
current_received_ts = 255.478210
current_seq = 8298
count = 65
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.461594/8297, current 255.478577/8298: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.478577
last_received_ts = 255.478210
last_seq = 8298
current_ts = 255.495560
current_received_ts = 255.495193
current_seq = 8299
count = 66
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.478577/8298, current 255.495560/8299: elapsed=16984.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.495560
last_received_ts = 255.495193
last_seq = 8299
current_ts = 255.512543
current_received_ts = 255.512222
current_seq = 8300
count = 67
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.495560/8299, current 255.512543/8300: elapsed=16976.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.512543
last_received_ts = 255.512222
last_seq = 8300
current_ts = 255.529541
current_received_ts = 255.529160
current_seq = 8301
count = 68
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.512543/8300, current 255.529541/8301: elapsed=16993.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.529541
last_received_ts = 255.529160
last_seq = 8301
current_ts = 255.546524
current_received_ts = 255.546173
current_seq = 8302
count = 69
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.529541/8301, current 255.546524/8302: elapsed=16983.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.546524
last_received_ts = 255.546173
last_seq = 8302
current_ts = 255.563507
current_received_ts = 255.563126
current_seq = 8303
count = 70
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.546524/8302, current 255.563507/8303: elapsed=16984.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.563507
last_received_ts = 255.563126
last_seq = 8303
current_ts = 255.580475
current_received_ts = 255.580185
current_seq = 8304
count = 71
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.563507/8303, current 255.580475/8304: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.580475
last_received_ts = 255.580185
last_seq = 8304
current_ts = 255.597473
current_received_ts = 255.597092
current_seq = 8305
count = 72
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.580475/8304, current 255.597473/8305: elapsed=16985.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.597473
last_received_ts = 255.597092
last_seq = 8305
current_ts = 255.614441
current_received_ts = 255.614105
current_seq = 8306
count = 73
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.597473/8305, current 255.614441/8306: elapsed=16981.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.614441
last_received_ts = 255.614105
last_seq = 8306
current_ts = 255.631439
current_received_ts = 255.631058
current_seq = 8307
count = 74
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.614441/8306, current 255.631439/8307: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.631439
last_received_ts = 255.631058
last_seq = 8307
current_ts = 255.648407
current_received_ts = 255.648132
current_seq = 8308
count = 75
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.631439/8307, current 255.648407/8308: elapsed=16974.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.648407
last_received_ts = 255.648132
last_seq = 8308
current_ts = 255.665405
current_received_ts = 255.665024
current_seq = 8309
count = 76
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.648407/8308, current 255.665405/8309: elapsed=16991.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.665405
last_received_ts = 255.665024
last_seq = 8309
current_ts = 255.682388
current_received_ts = 255.682037
current_seq = 8310
count = 77
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.665405/8309, current 255.682388/8310: elapsed=16989.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.682388
last_received_ts = 255.682037
last_seq = 8310
current_ts = 255.699371
current_received_ts = 255.698990
current_seq = 8311
count = 78
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.682388/8310, current 255.699371/8311: elapsed=16975.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.699371
last_received_ts = 255.698990
last_seq = 8311
current_ts = 255.716354
current_received_ts = 255.715973
current_seq = 8312
count = 79
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.699371/8311, current 255.716354/8312: elapsed=16987.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.716354
last_received_ts = 255.715973
last_seq = 8312
current_ts = 255.733337
current_received_ts = 255.732941
current_seq = 8313
count = 80
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.716354/8312, current 255.733337/8313: elapsed=16988.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.733337
last_received_ts = 255.732941
last_seq = 8313
current_ts = 255.750320
current_received_ts = 255.749924
current_seq = 8314
count = 81
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.733337/8313, current 255.750320/8314: elapsed=16976.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.750320
last_received_ts = 255.749924
last_seq = 8314
current_ts = 255.767303
current_received_ts = 255.766785
current_seq = 8315
count = 82
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.750320/8314, current 255.767303/8315: elapsed=16991.0us expected=17026.8us +- 85.1us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.767303
last_received_ts = 255.766785
last_seq = 8315
current_ts = 255.784286
current_received_ts = 255.783920
current_seq = 8316
count = 83
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.767303/8315, current 255.784286/8316: elapsed=16972.0us expected=17026.8us +- 85.1us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.784286
last_received_ts = 255.783920
last_seq = 8316
current_ts = 255.801239
current_received_ts = 255.800781
current_seq = 8317
count = 84
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.784286/8316, current 255.801239/8317: elapsed=16957.0us expected=17026.8us +- 85.1us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.801239
last_received_ts = 255.800781
last_seq = 8317
current_ts = 255.818176
current_received_ts = 255.817795
current_seq = 8318
count = 85
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.801239/8317, current 255.818176/8318: elapsed=16945.0us expected=17026.8us +- 85.1us, error 0.5%
(kms_flip:3996) DEBUG: name = flip
last_ts = 255.818176
last_received_ts = 255.817795
last_seq = 8318
current_ts = 255.835114
current_received_ts = 255.834732
current_seq = 8319
count = 86
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 255.818176/8318, current 255.835114/8319: elapsed=16937.0us expected=17026.8us +- 85.1us, error 0.5%
(kms_flip:3996) DEBUG: inconsistent flip ts/seq: last 255.818176/8318, current 255.835114/8319: elapsed=16937.0us expected=17026.8us
(kms_flip:3996) DEBUG: expected 0, counted 86, encoder type 2
(kms_flip:3996) DEBUG: dropped frames, expected 0, counted 86, encoder type 2
(kms_flip:3996) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3996) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3996) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3996) igt_core-INFO: Stack trace:
(kms_flip:3996) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:3996) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3996) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:3996) igt_core-INFO:   #3 ../tests/kms_flip.c:2121 __igt_unique____real_main2001()
(kms_flip:3996) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3996) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3996) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3996) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (5.111s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:3996) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3996) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3996) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.801483
last_received_ts = 260.801056
last_seq = 8606
current_ts = 260.818298
current_received_ts = 260.817841
current_seq = 8607
count = 78
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.801483/8606, current 260.818298/8607: elapsed=16804.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.818298
last_received_ts = 260.817841
last_seq = 8607
current_ts = 260.835114
current_received_ts = 260.834656
current_seq = 8608
count = 79
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.818298/8607, current 260.835114/8608: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.835114
last_received_ts = 260.834656
last_seq = 8608
current_ts = 260.851929
current_received_ts = 260.851471
current_seq = 8609
count = 80
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.835114/8608, current 260.851929/8609: elapsed=16826.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.851929
last_received_ts = 260.851471
last_seq = 8609
current_ts = 260.868744
current_received_ts = 260.868286
current_seq = 8610
count = 81
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.851929/8609, current 260.868744/8610: elapsed=16805.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.868744
last_received_ts = 260.868286
last_seq = 8610
current_ts = 260.885559
current_received_ts = 260.885223
current_seq = 8611
count = 82
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.868744/8610, current 260.885559/8611: elapsed=16823.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.885559
last_received_ts = 260.885223
last_seq = 8611
current_ts = 260.902374
current_received_ts = 260.901978
current_seq = 8612
count = 83
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.885559/8611, current 260.902374/8612: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.902374
last_received_ts = 260.901978
last_seq = 8612
current_ts = 260.919189
current_received_ts = 260.918732
current_seq = 8613
count = 84
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.902374/8612, current 260.919189/8613: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.919189
last_received_ts = 260.918732
last_seq = 8613
current_ts = 260.936005
current_received_ts = 260.935638
current_seq = 8614
count = 85
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.919189/8613, current 260.936005/8614: elapsed=16819.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.936005
last_received_ts = 260.935638
last_seq = 8614
current_ts = 260.952820
current_received_ts = 260.952484
current_seq = 8615
count = 86
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.936005/8614, current 260.952820/8615: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.952820
last_received_ts = 260.952484
last_seq = 8615
current_ts = 260.969635
current_received_ts = 260.969208
current_seq = 8616
count = 87
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.952820/8615, current 260.969635/8616: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.969635
last_received_ts = 260.969208
last_seq = 8616
current_ts = 260.986450
current_received_ts = 260.985992
current_seq = 8617
count = 88
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.969635/8616, current 260.986450/8617: elapsed=16819.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 260.986450
last_received_ts = 260.985992
last_seq = 8617
current_ts = 261.003265
current_received_ts = 261.002808
current_seq = 8618
count = 89
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 260.986450/8617, current 261.003265/8618: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.003265
last_received_ts = 261.002808
last_seq = 8618
current_ts = 261.020081
current_received_ts = 261.019623
current_seq = 8619
count = 90
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.003265/8618, current 261.020081/8619: elapsed=16812.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.020081
last_received_ts = 261.019623
last_seq = 8619
current_ts = 261.036896
current_received_ts = 261.036407
current_seq = 8620
count = 91
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.020081/8619, current 261.036896/8620: elapsed=16816.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.036896
last_received_ts = 261.036407
last_seq = 8620
current_ts = 261.053711
current_received_ts = 261.053131
current_seq = 8621
count = 92
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.036896/8620, current 261.053711/8621: elapsed=16816.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.053711
last_received_ts = 261.053131
last_seq = 8621
current_ts = 261.070526
current_received_ts = 261.070068
current_seq = 8622
count = 93
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.053711/8621, current 261.070526/8622: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.070526
last_received_ts = 261.070068
last_seq = 8622
current_ts = 261.087341
current_received_ts = 261.086884
current_seq = 8623
count = 94
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.070526/8622, current 261.087341/8623: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.087341
last_received_ts = 261.086884
last_seq = 8623
current_ts = 261.104126
current_received_ts = 261.103699
current_seq = 8624
count = 95
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.087341/8623, current 261.104126/8624: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.104126
last_received_ts = 261.103699
last_seq = 8624
current_ts = 261.120941
current_received_ts = 261.120483
current_seq = 8625
count = 96
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.104126/8624, current 261.120941/8625: elapsed=16812.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.120941
last_received_ts = 261.120483
last_seq = 8625
current_ts = 261.137787
current_received_ts = 261.137360
current_seq = 8626
count = 97
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.120941/8625, current 261.137787/8626: elapsed=16821.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.137787
last_received_ts = 261.137360
last_seq = 8626
current_ts = 261.154572
current_received_ts = 261.154144
current_seq = 8627
count = 98
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.137787/8626, current 261.154572/8627: elapsed=16808.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.154572
last_received_ts = 261.154144
last_seq = 8627
current_ts = 261.171387
current_received_ts = 261.170959
current_seq = 8628
count = 99
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.154572/8627, current 261.171387/8628: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.171387
last_received_ts = 261.170959
last_seq = 8628
current_ts = 261.188202
current_received_ts = 261.187775
current_seq = 8629
count = 100
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.171387/8628, current 261.188202/8629: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.188202
last_received_ts = 261.187775
last_seq = 8629
current_ts = 261.205017
current_received_ts = 261.204651
current_seq = 8630
count = 101
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.188202/8629, current 261.205017/8630: elapsed=16812.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.205017
last_received_ts = 261.204651
last_seq = 8630
current_ts = 261.221832
current_received_ts = 261.221497
current_seq = 8631
count = 102
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.205017/8630, current 261.221832/8631: elapsed=16821.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.221832
last_received_ts = 261.221497
last_seq = 8631
current_ts = 261.238647
current_received_ts = 261.238281
current_seq = 8632
count = 103
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.221832/8631, current 261.238647/8632: elapsed=16808.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.238647
last_received_ts = 261.238281
last_seq = 8632
current_ts = 261.255463
current_received_ts = 261.255096
current_seq = 8633
count = 104
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.238647/8632, current 261.255463/8633: elapsed=16821.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.255463
last_received_ts = 261.255096
last_seq = 8633
current_ts = 261.272278
current_received_ts = 261.271912
current_seq = 8634
count = 105
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.255463/8633, current 261.272278/8634: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.272278
last_received_ts = 261.271912
last_seq = 8634
current_ts = 261.289093
current_received_ts = 261.288666
current_seq = 8635
count = 106
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.272278/8634, current 261.289093/8635: elapsed=16814.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.289093
last_received_ts = 261.288666
last_seq = 8635
current_ts = 261.305908
current_received_ts = 261.305542
current_seq = 8636
count = 107
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.289093/8635, current 261.305908/8636: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.305908
last_received_ts = 261.305542
last_seq = 8636
current_ts = 261.322723
current_received_ts = 261.322205
current_seq = 8637
count = 108
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.305908/8636, current 261.322723/8637: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.322723
last_received_ts = 261.322205
last_seq = 8637
current_ts = 261.339539
current_received_ts = 261.339172
current_seq = 8638
count = 109
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.322723/8637, current 261.339539/8638: elapsed=16816.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.339539
last_received_ts = 261.339172
last_seq = 8638
current_ts = 261.356354
current_received_ts = 261.355804
current_seq = 8639
count = 110
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.339539/8638, current 261.356354/8639: elapsed=16814.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.356354
last_received_ts = 261.355804
last_seq = 8639
current_ts = 261.373169
current_received_ts = 261.372772
current_seq = 8640
count = 111
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.356354/8639, current 261.373169/8640: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.373169
last_received_ts = 261.372772
last_seq = 8640
current_ts = 261.389984
current_received_ts = 261.389465
current_seq = 8641
count = 112
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.373169/8640, current 261.389984/8641: elapsed=16817.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.389984
last_received_ts = 261.389465
last_seq = 8641
current_ts = 261.406799
current_received_ts = 261.406403
current_seq = 8642
count = 113
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.389984/8641, current 261.406799/8642: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.406799
last_received_ts = 261.406403
last_seq = 8642
current_ts = 261.423615
current_received_ts = 261.423248
current_seq = 8643
count = 114
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.406799/8642, current 261.423615/8643: elapsed=16818.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.423615
last_received_ts = 261.423248
last_seq = 8643
current_ts = 261.440430
current_received_ts = 261.440125
current_seq = 8644
count = 115
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.423615/8643, current 261.440430/8644: elapsed=16808.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.440430
last_received_ts = 261.440125
last_seq = 8644
current_ts = 261.457245
current_received_ts = 261.456909
current_seq = 8645
count = 116
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.440430/8644, current 261.457245/8645: elapsed=16821.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.457245
last_received_ts = 261.456909
last_seq = 8645
current_ts = 261.474060
current_received_ts = 261.473694
current_seq = 8646
count = 117
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.457245/8645, current 261.474060/8646: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.474060
last_received_ts = 261.473694
last_seq = 8646
current_ts = 261.490875
current_received_ts = 261.490479
current_seq = 8647
count = 118
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.474060/8646, current 261.490875/8647: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.490875
last_received_ts = 261.490479
last_seq = 8647
current_ts = 261.507690
current_received_ts = 261.507263
current_seq = 8648
count = 119
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.490875/8647, current 261.507690/8648: elapsed=16813.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.507690
last_received_ts = 261.507263
last_seq = 8648
current_ts = 261.524506
current_received_ts = 261.524261
current_seq = 8649
count = 120
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.507690/8648, current 261.524506/8649: elapsed=16817.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.524506
last_received_ts = 261.524261
last_seq = 8649
current_ts = 261.541321
current_received_ts = 261.540955
current_seq = 8650
count = 121
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.524506/8649, current 261.541321/8650: elapsed=16816.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.541321
last_received_ts = 261.540955
last_seq = 8650
current_ts = 261.558136
current_received_ts = 261.557770
current_seq = 8651
count = 122
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.541321/8650, current 261.558136/8651: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.558136
last_received_ts = 261.557770
last_seq = 8651
current_ts = 261.574951
current_received_ts = 261.574585
current_seq = 8652
count = 123
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.558136/8651, current 261.574951/8652: elapsed=16817.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.574951
last_received_ts = 261.574585
last_seq = 8652
current_ts = 261.591736
current_received_ts = 261.591400
current_seq = 8653
count = 124
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.574951/8652, current 261.591736/8653: elapsed=16812.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.591736
last_received_ts = 261.591400
last_seq = 8653
current_ts = 261.608551
current_received_ts = 261.608215
current_seq = 8654
count = 125
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.591736/8653, current 261.608551/8654: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.608551
last_received_ts = 261.608215
last_seq = 8654
current_ts = 261.625366
current_received_ts = 261.625000
current_seq = 8655
count = 126
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.608551/8654, current 261.625366/8655: elapsed=16814.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.625366
last_received_ts = 261.625000
last_seq = 8655
current_ts = 261.642181
current_received_ts = 261.641815
current_seq = 8656
count = 127
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.625366/8655, current 261.642181/8656: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.642181
last_received_ts = 261.641815
last_seq = 8656
current_ts = 261.658997
current_received_ts = 261.658630
current_seq = 8657
count = 128
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.642181/8656, current 261.658997/8657: elapsed=16817.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.658997
last_received_ts = 261.658630
last_seq = 8657
current_ts = 261.675812
current_received_ts = 261.675446
current_seq = 8658
count = 129
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.658997/8657, current 261.675812/8658: elapsed=16815.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.675812
last_received_ts = 261.675446
last_seq = 8658
current_ts = 261.692627
current_received_ts = 261.692200
current_seq = 8659
count = 130
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.675812/8658, current 261.692627/8659: elapsed=16817.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.692627
last_received_ts = 261.692200
last_seq = 8659
current_ts = 261.709442
current_received_ts = 261.709076
current_seq = 8660
count = 131
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.692627/8659, current 261.709442/8660: elapsed=16807.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.709442
last_received_ts = 261.709076
last_seq = 8660
current_ts = 261.726257
current_received_ts = 261.725861
current_seq = 8661
count = 132
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.709442/8660, current 261.726257/8661: elapsed=16820.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.726257
last_received_ts = 261.725861
last_seq = 8661
current_ts = 261.743073
current_received_ts = 261.742676
current_seq = 8662
count = 133
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.726257/8661, current 261.743073/8662: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.743073
last_received_ts = 261.742676
last_seq = 8662
current_ts = 261.759888
current_received_ts = 261.759521
current_seq = 8663
count = 134
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.743073/8662, current 261.759888/8663: elapsed=16819.0us expected=16856.8us +- 84.3us, error 0.2%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.759888
last_received_ts = 261.759521
last_seq = 8663
current_ts = 261.776703
current_received_ts = 261.776306
current_seq = 8664
count = 135
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.759888/8663, current 261.776703/8664: elapsed=16802.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.776703
last_received_ts = 261.776306
last_seq = 8664
current_ts = 261.793518
current_received_ts = 261.793121
current_seq = 8665
count = 136
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.776703/8664, current 261.793518/8665: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.793518
last_received_ts = 261.793121
last_seq = 8665
current_ts = 261.810303
current_received_ts = 261.809937
current_seq = 8666
count = 137
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.793518/8665, current 261.810303/8666: elapsed=16802.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.810303
last_received_ts = 261.809937
last_seq = 8666
current_ts = 261.827087
current_received_ts = 261.826721
current_seq = 8667
count = 138
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.810303/8666, current 261.827087/8667: elapsed=16786.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.827087
last_received_ts = 261.826721
last_seq = 8667
current_ts = 261.843903
current_received_ts = 261.843536
current_seq = 8668
count = 139
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.827087/8667, current 261.843903/8668: elapsed=16809.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.843903
last_received_ts = 261.843536
last_seq = 8668
current_ts = 261.860687
current_received_ts = 261.860229
current_seq = 8669
count = 140
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.843903/8668, current 261.860687/8669: elapsed=16790.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.860687
last_received_ts = 261.860229
last_seq = 8669
current_ts = 261.877502
current_received_ts = 261.877106
current_seq = 8670
count = 141
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.860687/8669, current 261.877502/8670: elapsed=16802.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.877502
last_received_ts = 261.877106
last_seq = 8670
current_ts = 261.894287
current_received_ts = 261.893921
current_seq = 8671
count = 142
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.877502/8670, current 261.894287/8671: elapsed=16795.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.894287
last_received_ts = 261.893921
last_seq = 8671
current_ts = 261.911072
current_received_ts = 261.910614
current_seq = 8672
count = 143
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.894287/8671, current 261.911072/8672: elapsed=16790.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.911072
last_received_ts = 261.910614
last_seq = 8672
current_ts = 261.927887
current_received_ts = 261.927521
current_seq = 8673
count = 144
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.911072/8672, current 261.927887/8673: elapsed=16807.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.927887
last_received_ts = 261.927521
last_seq = 8673
current_ts = 261.944672
current_received_ts = 261.944366
current_seq = 8674
count = 145
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.927887/8673, current 261.944672/8674: elapsed=16785.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.944672
last_received_ts = 261.944366
last_seq = 8674
current_ts = 261.961487
current_received_ts = 261.961029
current_seq = 8675
count = 146
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.944672/8674, current 261.961487/8675: elapsed=16806.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.961487
last_received_ts = 261.961029
last_seq = 8675
current_ts = 261.978271
current_received_ts = 261.977783
current_seq = 8676
count = 147
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.961487/8675, current 261.978271/8676: elapsed=16801.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.978271
last_received_ts = 261.977783
last_seq = 8676
current_ts = 261.995056
current_received_ts = 261.994598
current_seq = 8677
count = 148
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.978271/8676, current 261.995056/8677: elapsed=16784.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 261.995056
last_received_ts = 261.994598
last_seq = 8677
current_ts = 262.011871
current_received_ts = 262.011414
current_seq = 8678
count = 149
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 261.995056/8677, current 262.011871/8678: elapsed=16798.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.011871
last_received_ts = 262.011414
last_seq = 8678
current_ts = 262.028656
current_received_ts = 262.028259
current_seq = 8679
count = 150
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.011871/8678, current 262.028656/8679: elapsed=16797.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.028656
last_received_ts = 262.028259
last_seq = 8679
current_ts = 262.045471
current_received_ts = 262.045013
current_seq = 8680
count = 151
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.028656/8679, current 262.045471/8680: elapsed=16798.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.045471
last_received_ts = 262.045013
last_seq = 8680
current_ts = 262.062256
current_received_ts = 262.061829
current_seq = 8681
count = 152
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.045471/8680, current 262.062256/8681: elapsed=16799.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.062256
last_received_ts = 262.061829
last_seq = 8681
current_ts = 262.079041
current_received_ts = 262.078583
current_seq = 8682
count = 153
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.062256/8681, current 262.079041/8682: elapsed=16791.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.079041
last_received_ts = 262.078583
last_seq = 8682
current_ts = 262.095856
current_received_ts = 262.095398
current_seq = 8683
count = 154
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.079041/8682, current 262.095856/8683: elapsed=16803.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.095856
last_received_ts = 262.095398
last_seq = 8683
current_ts = 262.112640
current_received_ts = 262.112152
current_seq = 8684
count = 155
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.095856/8683, current 262.112640/8684: elapsed=16803.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.112640
last_received_ts = 262.112152
last_seq = 8684
current_ts = 262.129425
current_received_ts = 262.128998
current_seq = 8685
count = 156
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.112640/8684, current 262.129425/8685: elapsed=16787.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.129425
last_received_ts = 262.128998
last_seq = 8685
current_ts = 262.146240
current_received_ts = 262.145782
current_seq = 8686
count = 157
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.129425/8685, current 262.146240/8686: elapsed=16798.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.146240
last_received_ts = 262.145782
last_seq = 8686
current_ts = 262.163025
current_received_ts = 262.162567
current_seq = 8687
count = 158
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.146240/8686, current 262.163025/8687: elapsed=16795.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.163025
last_received_ts = 262.162567
last_seq = 8687
current_ts = 262.179840
current_received_ts = 262.179413
current_seq = 8688
count = 159
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.163025/8687, current 262.179840/8688: elapsed=16803.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.179840
last_received_ts = 262.179413
last_seq = 8688
current_ts = 262.196625
current_received_ts = 262.196167
current_seq = 8689
count = 160
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.179840/8688, current 262.196625/8689: elapsed=16801.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.196625
last_received_ts = 262.196167
last_seq = 8689
current_ts = 262.213409
current_received_ts = 262.212982
current_seq = 8690
count = 161
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.196625/8689, current 262.213409/8690: elapsed=16786.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.213409
last_received_ts = 262.212982
last_seq = 8690
current_ts = 262.230225
current_received_ts = 262.229797
current_seq = 8691
count = 162
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.213409/8690, current 262.230225/8691: elapsed=16808.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.230225
last_received_ts = 262.229797
last_seq = 8691
current_ts = 262.247040
current_received_ts = 262.246582
current_seq = 8692
count = 163
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.230225/8691, current 262.247040/8692: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.247040
last_received_ts = 262.246582
last_seq = 8692
current_ts = 262.263824
current_received_ts = 262.263367
current_seq = 8693
count = 164
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.247040/8692, current 262.263824/8693: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.263824
last_received_ts = 262.263367
last_seq = 8693
current_ts = 262.280609
current_received_ts = 262.280151
current_seq = 8694
count = 165
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.263824/8693, current 262.280609/8694: elapsed=16786.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.280609
last_received_ts = 262.280151
last_seq = 8694
current_ts = 262.297394
current_received_ts = 262.296906
current_seq = 8695
count = 166
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.280609/8694, current 262.297394/8695: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.297394
last_received_ts = 262.296906
last_seq = 8695
current_ts = 262.314209
current_received_ts = 262.313751
current_seq = 8696
count = 167
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.297394/8695, current 262.314209/8696: elapsed=16801.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.314209
last_received_ts = 262.313751
last_seq = 8696
current_ts = 262.330994
current_received_ts = 262.330627
current_seq = 8697
count = 168
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.314209/8696, current 262.330994/8697: elapsed=16803.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.330994
last_received_ts = 262.330627
last_seq = 8697
current_ts = 262.347809
current_received_ts = 262.347473
current_seq = 8698
count = 169
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.330994/8697, current 262.347809/8698: elapsed=16787.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.347809
last_received_ts = 262.347473
last_seq = 8698
current_ts = 262.364594
current_received_ts = 262.364197
current_seq = 8699
count = 170
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.347809/8698, current 262.364594/8699: elapsed=16807.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.364594
last_received_ts = 262.364197
last_seq = 8699
current_ts = 262.381409
current_received_ts = 262.381042
current_seq = 8700
count = 171
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.364594/8699, current 262.381409/8700: elapsed=16798.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.381409
last_received_ts = 262.381042
last_seq = 8700
current_ts = 262.398193
current_received_ts = 262.397827
current_seq = 8701
count = 172
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.381409/8700, current 262.398193/8701: elapsed=16794.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.398193
last_received_ts = 262.397827
last_seq = 8701
current_ts = 262.414978
current_received_ts = 262.414612
current_seq = 8702
count = 173
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.398193/8701, current 262.414978/8702: elapsed=16794.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.414978
last_received_ts = 262.414612
last_seq = 8702
current_ts = 262.431793
current_received_ts = 262.431396
current_seq = 8703
count = 174
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.414978/8702, current 262.431793/8703: elapsed=16802.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.431793
last_received_ts = 262.431396
last_seq = 8703
current_ts = 262.448578
current_received_ts = 262.448181
current_seq = 8704
count = 175
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.431793/8703, current 262.448578/8704: elapsed=16785.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.448578
last_received_ts = 262.448181
last_seq = 8704
current_ts = 262.465393
current_received_ts = 262.464966
current_seq = 8705
count = 176
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.448578/8704, current 262.465393/8705: elapsed=16807.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.465393
last_received_ts = 262.464966
last_seq = 8705
current_ts = 262.482178
current_received_ts = 262.481812
current_seq = 8706
count = 177
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.465393/8705, current 262.482178/8706: elapsed=16795.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.482178
last_received_ts = 262.481812
last_seq = 8706
current_ts = 262.498962
current_received_ts = 262.498596
current_seq = 8707
count = 178
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.482178/8706, current 262.498962/8707: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.498962
last_received_ts = 262.498596
last_seq = 8707
current_ts = 262.515778
current_received_ts = 262.515381
current_seq = 8708
count = 179
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.498962/8707, current 262.515778/8708: elapsed=16794.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.515778
last_received_ts = 262.515381
last_seq = 8708
current_ts = 262.532562
current_received_ts = 262.532288
current_seq = 8709
count = 180
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.515778/8708, current 262.532562/8709: elapsed=16803.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.532562
last_received_ts = 262.532288
last_seq = 8709
current_ts = 262.549377
current_received_ts = 262.548889
current_seq = 8710
count = 181
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.532562/8709, current 262.549377/8710: elapsed=16795.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.549377
last_received_ts = 262.548889
last_seq = 8710
current_ts = 262.566162
current_received_ts = 262.565735
current_seq = 8711
count = 182
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.549377/8710, current 262.566162/8711: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.566162
last_received_ts = 262.565735
last_seq = 8711
current_ts = 262.582947
current_received_ts = 262.582611
current_seq = 8712
count = 183
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.566162/8711, current 262.582947/8712: elapsed=16796.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.582947
last_received_ts = 262.582611
last_seq = 8712
current_ts = 262.599762
current_received_ts = 262.599426
current_seq = 8713
count = 184
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.582947/8712, current 262.599762/8713: elapsed=16801.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.599762
last_received_ts = 262.599426
last_seq = 8713
current_ts = 262.616547
current_received_ts = 262.616150
current_seq = 8714
count = 185
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.599762/8713, current 262.616547/8714: elapsed=16785.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.616547
last_received_ts = 262.616150
last_seq = 8714
current_ts = 262.633362
current_received_ts = 262.632996
current_seq = 8715
count = 186
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.616547/8714, current 262.633362/8715: elapsed=16810.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.633362
last_received_ts = 262.632996
last_seq = 8715
current_ts = 262.650146
current_received_ts = 262.649780
current_seq = 8716
count = 187
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.633362/8715, current 262.650146/8716: elapsed=16787.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.650146
last_received_ts = 262.649780
last_seq = 8716
current_ts = 262.666962
current_received_ts = 262.666443
current_seq = 8717
count = 188
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.650146/8716, current 262.666962/8717: elapsed=16807.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.666962
last_received_ts = 262.666443
last_seq = 8717
current_ts = 262.683746
current_received_ts = 262.683380
current_seq = 8718
count = 189
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.666962/8717, current 262.683746/8718: elapsed=16791.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.683746
last_received_ts = 262.683380
last_seq = 8718
current_ts = 262.700531
current_received_ts = 262.699982
current_seq = 8719
count = 190
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.683746/8718, current 262.700531/8719: elapsed=16798.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.700531
last_received_ts = 262.699982
last_seq = 8719
current_ts = 262.717346
current_received_ts = 262.716980
current_seq = 8720
count = 191
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.700531/8719, current 262.717346/8720: elapsed=16795.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.717346
last_received_ts = 262.716980
last_seq = 8720
current_ts = 262.734131
current_received_ts = 262.733612
current_seq = 8721
count = 192
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.717346/8720, current 262.734131/8721: elapsed=16792.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.734131
last_received_ts = 262.733612
last_seq = 8721
current_ts = 262.750916
current_received_ts = 262.750549
current_seq = 8722
count = 193
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.734131/8721, current 262.750916/8722: elapsed=16804.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.750916
last_received_ts = 262.750549
last_seq = 8722
current_ts = 262.767731
current_received_ts = 262.767212
current_seq = 8723
count = 194
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.750916/8722, current 262.767731/8723: elapsed=16801.0us expected=16856.8us +- 84.3us, error 0.3%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.767731
last_received_ts = 262.767212
last_seq = 8723
current_ts = 262.784515
current_received_ts = 262.784149
current_seq = 8724
count = 195
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.767731/8723, current 262.784515/8724: elapsed=16794.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.784515
last_received_ts = 262.784149
last_seq = 8724
current_ts = 262.801300
current_received_ts = 262.800873
current_seq = 8725
count = 196
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.784515/8724, current 262.801300/8725: elapsed=16784.0us expected=16856.8us +- 84.3us, error 0.4%
(kms_flip:3996) DEBUG: name = flip
last_ts = 262.801300
last_received_ts = 262.800873
last_seq = 8725
current_ts = 262.818085
current_received_ts = 262.817596
current_seq = 8726
count = 197
seq_step = 1
(kms_flip:3996) DEBUG: flip ts/seq: last 262.801300/8725, current 262.818085/8726: elapsed=16772.0us expected=16856.8us +- 84.3us, error 0.5%
(kms_flip:3996) DEBUG: inconsistent flip ts/seq: last 262.801300/8725, current 262.818085/8726: elapsed=16772.0us expected=16856.8us
(kms_flip:3996) DEBUG: expected 0, counted 197, encoder type 2
(kms_flip:3996) DEBUG: dropped frames, expected 0, counted 197, encoder type 2
(kms_flip:3996) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3996) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3996) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:3996) igt_core-INFO: Stack trace:
(kms_flip:3996) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:3996) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3996) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:3996) igt_core-INFO:   #3 ../tests/kms_flip.c:2121 __igt_unique____real_main2001()
(kms_flip:3996) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3996) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3996) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3996) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (6.936s)
Starting dynamic subtest: AD-DP2-HDMI-A3
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.629s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.644s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.613s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.629s)
Subtest 2x-plain-flip-ts-check-interruptible: FAIL (34.602s)