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

shard-lnl-5

IGT-Version: 1.30-gbd401847a (x86_64) (Linux: 6.14.0-rc4-xe+ x86_64)

Using IGT_SRANDOM=1740781187 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16284.0us +- 3.502us accuracy 0.06%
vblank interval differs from modeline! expected 16664.0us, measured 16284us +- 3.502us, difference 380.0us (108.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __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 A-eDP1: FAIL (5.814s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16488.9us +- 3.838us accuracy 0.07%
vblank interval differs from modeline! expected 16664.0us, measured 16489us +- 3.838us, difference 175.1us (45.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __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 B-eDP1: FAIL (9.304s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16605.8us +- 2.887us accuracy 0.05%
vblank interval differs from modeline! expected 16664.0us, measured 16606us +- 2.887us, difference 58.3us (20.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __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 C-eDP1: FAIL (14.727s)
Subtest plain-flip-ts-check: FAIL (29.853s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2809) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2809) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=11520)
(kms_flip:2809) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2809) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2809) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
(kms_flip:2809) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2809) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce63350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce63350, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce70970, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce70970, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce6ce80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce6ce80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce6ce80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) intel_allocator_simple-DEBUG: <ial: 0x63c4fce6ce80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2809) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
(kms_flip:2809) DEBUG: No stale events found
(kms_flip:2809) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2809) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2809) INFO: Expected frametime: 16664us; measured 16284.0us +- 3.502us accuracy 0.06%
(kms_flip:2809) INFO: vblank interval differs from modeline! expected 16664.0us, measured 16284us +- 3.502us, difference 380.0us (108.5 sigma)
(kms_flip:2809) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 147.540894
current_received_ts = 147.540207
current_seq = 2738
count = 0
seq_step = 1
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.540894
last_received_ts = 147.540207
last_seq = 2738
current_ts = 147.557190
current_received_ts = 147.556610
current_seq = 2739
count = 1
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.540894/2738, current 147.557190/2739: elapsed=16295.0us expected=16284.0us +- 81.4us, error 0.1%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.557190
last_received_ts = 147.556610
last_seq = 2739
current_ts = 147.573517
current_received_ts = 147.572968
current_seq = 2740
count = 2
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.557190/2739, current 147.573517/2740: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.573517
last_received_ts = 147.572968
last_seq = 2740
current_ts = 147.589844
current_received_ts = 147.589264
current_seq = 2741
count = 3
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.573517/2740, current 147.589844/2741: elapsed=16325.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.589844
last_received_ts = 147.589264
last_seq = 2741
current_ts = 147.606171
current_received_ts = 147.605743
current_seq = 2742
count = 4
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.589844/2741, current 147.606171/2742: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.606171
last_received_ts = 147.605743
last_seq = 2742
current_ts = 147.622498
current_received_ts = 147.621918
current_seq = 2743
count = 5
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.606171/2742, current 147.622498/2743: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.622498
last_received_ts = 147.621918
last_seq = 2743
current_ts = 147.638840
current_received_ts = 147.638290
current_seq = 2744
count = 6
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.622498/2743, current 147.638840/2744: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.638840
last_received_ts = 147.638290
last_seq = 2744
current_ts = 147.655167
current_received_ts = 147.654755
current_seq = 2745
count = 7
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.638840/2744, current 147.655167/2745: elapsed=16332.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.655167
last_received_ts = 147.654755
last_seq = 2745
current_ts = 147.671509
current_received_ts = 147.670944
current_seq = 2746
count = 8
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.655167/2745, current 147.671509/2746: elapsed=16334.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.671509
last_received_ts = 147.670944
last_seq = 2746
current_ts = 147.687836
current_received_ts = 147.687424
current_seq = 2747
count = 9
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.671509/2746, current 147.687836/2747: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.687836
last_received_ts = 147.687424
last_seq = 2747
current_ts = 147.704163
current_received_ts = 147.703735
current_seq = 2748
count = 10
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.687836/2747, current 147.704163/2748: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.704163
last_received_ts = 147.703735
last_seq = 2748
current_ts = 147.720490
current_received_ts = 147.719910
current_seq = 2749
count = 11
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.704163/2748, current 147.720490/2749: elapsed=16329.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.720490
last_received_ts = 147.719910
last_seq = 2749
current_ts = 147.736832
current_received_ts = 147.736160
current_seq = 2750
count = 12
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.720490/2749, current 147.736832/2750: elapsed=16335.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.736832
last_received_ts = 147.736160
last_seq = 2750
current_ts = 147.753159
current_received_ts = 147.752533
current_seq = 2751
count = 13
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.736832/2750, current 147.753159/2751: elapsed=16326.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.753159
last_received_ts = 147.752533
last_seq = 2751
current_ts = 147.769485
current_received_ts = 147.768921
current_seq = 2752
count = 14
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.753159/2751, current 147.769485/2752: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.769485
last_received_ts = 147.768921
last_seq = 2752
current_ts = 147.785812
current_received_ts = 147.785172
current_seq = 2753
count = 15
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.769485/2752, current 147.785812/2753: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.785812
last_received_ts = 147.785172
last_seq = 2753
current_ts = 147.802139
current_received_ts = 147.801559
current_seq = 2754
count = 16
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.785812/2753, current 147.802139/2754: elapsed=16332.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.802139
last_received_ts = 147.801559
last_seq = 2754
current_ts = 147.818481
current_received_ts = 147.817917
current_seq = 2755
count = 17
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.802139/2754, current 147.818481/2755: elapsed=16334.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.818481
last_received_ts = 147.817917
last_seq = 2755
current_ts = 147.834808
current_received_ts = 147.834183
current_seq = 2756
count = 18
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.818481/2755, current 147.834808/2756: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.834808
last_received_ts = 147.834183
last_seq = 2756
current_ts = 147.851135
current_received_ts = 147.850540
current_seq = 2757
count = 19
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.834808/2756, current 147.851135/2757: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.851135
last_received_ts = 147.850540
last_seq = 2757
current_ts = 147.867462
current_received_ts = 147.866913
current_seq = 2758
count = 20
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.851135/2757, current 147.867462/2758: elapsed=16329.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.867462
last_received_ts = 147.866913
last_seq = 2758
current_ts = 147.883789
current_received_ts = 147.883179
current_seq = 2759
count = 21
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.867462/2758, current 147.883789/2759: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.883789
last_received_ts = 147.883179
last_seq = 2759
current_ts = 147.900131
current_received_ts = 147.899704
current_seq = 2760
count = 22
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.883789/2759, current 147.900131/2760: elapsed=16334.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.900131
last_received_ts = 147.899704
last_seq = 2760
current_ts = 147.916458
current_received_ts = 147.915894
current_seq = 2761
count = 23
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.900131/2760, current 147.916458/2761: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.916458
last_received_ts = 147.915894
last_seq = 2761
current_ts = 147.932785
current_received_ts = 147.932144
current_seq = 2762
count = 24
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.916458/2761, current 147.932785/2762: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.932785
last_received_ts = 147.932144
last_seq = 2762
current_ts = 147.949127
current_received_ts = 147.948456
current_seq = 2763
count = 25
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.932785/2762, current 147.949127/2763: elapsed=16332.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.949127
last_received_ts = 147.948456
last_seq = 2763
current_ts = 147.965454
current_received_ts = 147.965088
current_seq = 2764
count = 26
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.949127/2763, current 147.965454/2764: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.965454
last_received_ts = 147.965088
last_seq = 2764
current_ts = 147.981781
current_received_ts = 147.981201
current_seq = 2765
count = 27
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.965454/2764, current 147.981781/2765: elapsed=16336.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.981781
last_received_ts = 147.981201
last_seq = 2765
current_ts = 147.998108
current_received_ts = 147.997513
current_seq = 2766
count = 28
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.981781/2765, current 147.998108/2766: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 147.998108
last_received_ts = 147.997513
last_seq = 2766
current_ts = 148.014450
current_received_ts = 148.013885
current_seq = 2767
count = 29
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 147.998108/2766, current 148.014450/2767: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.014450
last_received_ts = 148.013885
last_seq = 2767
current_ts = 148.030777
current_received_ts = 148.030167
current_seq = 2768
count = 30
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.014450/2767, current 148.030777/2768: elapsed=16332.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.030777
last_received_ts = 148.030167
last_seq = 2768
current_ts = 148.047104
current_received_ts = 148.046448
current_seq = 2769
count = 31
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.030777/2768, current 148.047104/2769: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.047104
last_received_ts = 148.046448
last_seq = 2769
current_ts = 148.063431
current_received_ts = 148.062851
current_seq = 2770
count = 32
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.047104/2769, current 148.063431/2770: elapsed=16326.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.063431
last_received_ts = 148.062851
last_seq = 2770
current_ts = 148.079773
current_received_ts = 148.079163
current_seq = 2771
count = 33
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.063431/2770, current 148.079773/2771: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.079773
last_received_ts = 148.079163
last_seq = 2771
current_ts = 148.096100
current_received_ts = 148.095428
current_seq = 2772
count = 34
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.079773/2771, current 148.096100/2772: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.096100
last_received_ts = 148.095428
last_seq = 2772
current_ts = 148.112427
current_received_ts = 148.111862
current_seq = 2773
count = 35
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.096100/2772, current 148.112427/2773: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.112427
last_received_ts = 148.111862
last_seq = 2773
current_ts = 148.128754
current_received_ts = 148.128159
current_seq = 2774
count = 36
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.112427/2773, current 148.128754/2774: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.128754
last_received_ts = 148.128159
last_seq = 2774
current_ts = 148.145081
current_received_ts = 148.144470
current_seq = 2775
count = 37
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.128754/2774, current 148.145081/2775: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.145081
last_received_ts = 148.144470
last_seq = 2775
current_ts = 148.161423
current_received_ts = 148.160858
current_seq = 2776
count = 38
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.145081/2775, current 148.161423/2776: elapsed=16336.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.161423
last_received_ts = 148.160858
last_seq = 2776
current_ts = 148.177750
current_received_ts = 148.177139
current_seq = 2777
count = 39
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.161423/2776, current 148.177750/2777: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.177750
last_received_ts = 148.177139
last_seq = 2777
current_ts = 148.194077
current_received_ts = 148.193405
current_seq = 2778
count = 40
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.177750/2777, current 148.194077/2778: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.194077
last_received_ts = 148.193405
last_seq = 2778
current_ts = 148.210419
current_received_ts = 148.209854
current_seq = 2779
count = 41
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.194077/2778, current 148.210419/2779: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.210419
last_received_ts = 148.209854
last_seq = 2779
current_ts = 148.226746
current_received_ts = 148.226166
current_seq = 2780
count = 42
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.210419/2779, current 148.226746/2780: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.226746
last_received_ts = 148.226166
last_seq = 2780
current_ts = 148.243073
current_received_ts = 148.242447
current_seq = 2781
count = 43
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.226746/2780, current 148.243073/2781: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.243073
last_received_ts = 148.242447
last_seq = 2781
current_ts = 148.259399
current_received_ts = 148.258820
current_seq = 2782
count = 44
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.243073/2781, current 148.259399/2782: elapsed=16323.0us expected=16284.0us +- 81.4us, error 0.2%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.259399
last_received_ts = 148.258820
last_seq = 2782
current_ts = 148.275726
current_received_ts = 148.275162
current_seq = 2783
count = 45
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.259399/2782, current 148.275726/2783: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.275726
last_received_ts = 148.275162
last_seq = 2783
current_ts = 148.292068
current_received_ts = 148.291656
current_seq = 2784
count = 46
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.275726/2783, current 148.292068/2784: elapsed=16336.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.292068
last_received_ts = 148.291656
last_seq = 2784
current_ts = 148.308395
current_received_ts = 148.307831
current_seq = 2785
count = 47
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.292068/2784, current 148.308395/2785: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.308395
last_received_ts = 148.307831
last_seq = 2785
current_ts = 148.324722
current_received_ts = 148.324142
current_seq = 2786
count = 48
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.308395/2785, current 148.324722/2786: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.324722
last_received_ts = 148.324142
last_seq = 2786
current_ts = 148.341064
current_received_ts = 148.340637
current_seq = 2787
count = 49
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.324722/2786, current 148.341064/2787: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.341064
last_received_ts = 148.340637
last_seq = 2787
current_ts = 148.357391
current_received_ts = 148.356842
current_seq = 2788
count = 50
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.341064/2787, current 148.357391/2788: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.357391
last_received_ts = 148.356842
last_seq = 2788
current_ts = 148.373718
current_received_ts = 148.373154
current_seq = 2789
count = 51
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.357391/2788, current 148.373718/2789: elapsed=16332.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.373718
last_received_ts = 148.373154
last_seq = 2789
current_ts = 148.390060
current_received_ts = 148.389404
current_seq = 2790
count = 52
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.373718/2789, current 148.390060/2790: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.390060
last_received_ts = 148.389404
last_seq = 2790
current_ts = 148.406387
current_received_ts = 148.405807
current_seq = 2791
count = 53
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.390060/2790, current 148.406387/2791: elapsed=16330.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.406387
last_received_ts = 148.405807
last_seq = 2791
current_ts = 148.422714
current_received_ts = 148.422150
current_seq = 2792
count = 54
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.406387/2791, current 148.422714/2792: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.422714
last_received_ts = 148.422150
last_seq = 2792
current_ts = 148.439041
current_received_ts = 148.438339
current_seq = 2793
count = 55
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.422714/2792, current 148.439041/2793: elapsed=16327.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.439041
last_received_ts = 148.438339
last_seq = 2793
current_ts = 148.455368
current_received_ts = 148.454788
current_seq = 2794
count = 56
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.439041/2793, current 148.455368/2794: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.455368
last_received_ts = 148.454788
last_seq = 2794
current_ts = 148.471695
current_received_ts = 148.471130
current_seq = 2795
count = 57
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.455368/2794, current 148.471695/2795: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.471695
last_received_ts = 148.471130
last_seq = 2795
current_ts = 148.488037
current_received_ts = 148.487289
current_seq = 2796
count = 58
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.471695/2795, current 148.488037/2796: elapsed=16334.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.488037
last_received_ts = 148.487289
last_seq = 2796
current_ts = 148.504364
current_received_ts = 148.503799
current_seq = 2797
count = 59
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.488037/2796, current 148.504364/2797: elapsed=16331.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.504364
last_received_ts = 148.503799
last_seq = 2797
current_ts = 148.520691
current_received_ts = 148.520157
current_seq = 2798
count = 60
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.504364/2797, current 148.520691/2798: elapsed=16333.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.520691
last_received_ts = 148.520157
last_seq = 2798
current_ts = 148.537033
current_received_ts = 148.536301
current_seq = 2799
count = 61
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.520691/2798, current 148.537033/2799: elapsed=16328.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.537033
last_received_ts = 148.536301
last_seq = 2799
current_ts = 148.553360
current_received_ts = 148.552795
current_seq = 2800
count = 62
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.537033/2799, current 148.553360/2800: elapsed=16334.0us expected=16284.0us +- 81.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.553360
last_received_ts = 148.552795
last_seq = 2800
current_ts = 148.569717
current_received_ts = 148.569183
current_seq = 2801
count = 63
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.553360/2800, current 148.569717/2801: elapsed=16362.0us expected=16284.0us +- 81.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 148.569717
last_received_ts = 148.569183
last_seq = 2801
current_ts = 148.586090
current_received_ts = 148.585510
current_seq = 2802
count = 64
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 148.569717/2801, current 148.586090/2802: elapsed=16375.0us expected=16284.0us +- 81.4us, error 0.6%
(kms_flip:2809) DEBUG: inconsistent flip ts/seq: last 148.569717/2801, current 148.586090/2802: elapsed=16375.0us expected=16284.0us
(kms_flip:2809) DEBUG: expected 68851, counted 64, encoder type 2
(kms_flip:2809) DEBUG: dropped frames, expected 68851, counted 64, encoder type 2
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2809) igt_core-INFO: Stack trace:
(kms_flip:2809) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2809) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2809) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2809) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2809) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2809) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2809) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2809) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (5.814s)
Starting dynamic subtest: B-eDP1
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2809) DEBUG: flip ts/seq: last 155.603317/382, current 155.619858/383: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.619858
last_received_ts = 155.619293
last_seq = 383
current_ts = 155.636414
current_received_ts = 155.636063
current_seq = 384
count = 147
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.619858/383, current 155.636414/384: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.636414
last_received_ts = 155.636063
last_seq = 384
current_ts = 155.652954
current_received_ts = 155.652344
current_seq = 385
count = 148
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.636414/384, current 155.652954/385: elapsed=16550.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.652954
last_received_ts = 155.652344
last_seq = 385
current_ts = 155.669495
current_received_ts = 155.668930
current_seq = 386
count = 149
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.652954/385, current 155.669495/386: elapsed=16539.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.669495
last_received_ts = 155.668930
last_seq = 386
current_ts = 155.686050
current_received_ts = 155.685333
current_seq = 387
count = 150
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.669495/386, current 155.686050/387: elapsed=16549.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.686050
last_received_ts = 155.685333
last_seq = 387
current_ts = 155.702576
current_received_ts = 155.702042
current_seq = 388
count = 151
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.686050/387, current 155.702576/388: elapsed=16537.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.702576
last_received_ts = 155.702042
last_seq = 388
current_ts = 155.719131
current_received_ts = 155.718521
current_seq = 389
count = 152
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.702576/388, current 155.719131/389: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.719131
last_received_ts = 155.718521
last_seq = 389
current_ts = 155.735672
current_received_ts = 155.735123
current_seq = 390
count = 153
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.719131/389, current 155.735672/390: elapsed=16549.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.735672
last_received_ts = 155.735123
last_seq = 390
current_ts = 155.752213
current_received_ts = 155.751785
current_seq = 391
count = 154
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.735672/390, current 155.752213/391: elapsed=16536.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.752213
last_received_ts = 155.751785
last_seq = 391
current_ts = 155.768768
current_received_ts = 155.768173
current_seq = 392
count = 155
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.752213/391, current 155.768768/392: elapsed=16550.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.768768
last_received_ts = 155.768173
last_seq = 392
current_ts = 155.785309
current_received_ts = 155.784744
current_seq = 393
count = 156
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.768768/392, current 155.785309/393: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.785309
last_received_ts = 155.784744
last_seq = 393
current_ts = 155.801849
current_received_ts = 155.801285
current_seq = 394
count = 157
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.785309/393, current 155.801849/394: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.801849
last_received_ts = 155.801285
last_seq = 394
current_ts = 155.818390
current_received_ts = 155.817825
current_seq = 395
count = 158
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.801849/394, current 155.818390/395: elapsed=16540.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.818390
last_received_ts = 155.817825
last_seq = 395
current_ts = 155.834930
current_received_ts = 155.834335
current_seq = 396
count = 159
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.818390/395, current 155.834930/396: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.834930
last_received_ts = 155.834335
last_seq = 396
current_ts = 155.851486
current_received_ts = 155.850922
current_seq = 397
count = 160
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.834930/396, current 155.851486/397: elapsed=16548.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.851486
last_received_ts = 155.850922
last_seq = 397
current_ts = 155.868027
current_received_ts = 155.867340
current_seq = 398
count = 161
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.851486/397, current 155.868027/398: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.868027
last_received_ts = 155.867340
last_seq = 398
current_ts = 155.884567
current_received_ts = 155.884048
current_seq = 399
count = 162
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.868027/398, current 155.884567/399: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.884567
last_received_ts = 155.884048
last_seq = 399
current_ts = 155.901108
current_received_ts = 155.900436
current_seq = 400
count = 163
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.884567/399, current 155.901108/400: elapsed=16541.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.901108
last_received_ts = 155.900436
last_seq = 400
current_ts = 155.917664
current_received_ts = 155.917099
current_seq = 401
count = 164
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.901108/400, current 155.917664/401: elapsed=16549.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.917664
last_received_ts = 155.917099
last_seq = 401
current_ts = 155.934204
current_received_ts = 155.933594
current_seq = 402
count = 165
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.917664/401, current 155.934204/402: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.934204
last_received_ts = 155.933594
last_seq = 402
current_ts = 155.950745
current_received_ts = 155.950195
current_seq = 403
count = 166
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.934204/402, current 155.950745/403: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.950745
last_received_ts = 155.950195
last_seq = 403
current_ts = 155.967285
current_received_ts = 155.966705
current_seq = 404
count = 167
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.950745/403, current 155.967285/404: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.967285
last_received_ts = 155.966705
last_seq = 404
current_ts = 155.983826
current_received_ts = 155.983307
current_seq = 405
count = 168
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.967285/404, current 155.983826/405: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 155.983826
last_received_ts = 155.983307
last_seq = 405
current_ts = 156.000381
current_received_ts = 155.999985
current_seq = 406
count = 169
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 155.983826/405, current 156.000381/406: elapsed=16547.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.000381
last_received_ts = 155.999985
last_seq = 406
current_ts = 156.016922
current_received_ts = 156.016327
current_seq = 407
count = 170
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.000381/406, current 156.016922/407: elapsed=16541.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.016922
last_received_ts = 156.016327
last_seq = 407
current_ts = 156.033463
current_received_ts = 156.032898
current_seq = 408
count = 171
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.016922/407, current 156.033463/408: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.033463
last_received_ts = 156.032898
last_seq = 408
current_ts = 156.050018
current_received_ts = 156.049393
current_seq = 409
count = 172
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.033463/408, current 156.050018/409: elapsed=16547.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.050018
last_received_ts = 156.049393
last_seq = 409
current_ts = 156.066559
current_received_ts = 156.066040
current_seq = 410
count = 173
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.050018/409, current 156.066559/410: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.066559
last_received_ts = 156.066040
last_seq = 410
current_ts = 156.083099
current_received_ts = 156.082443
current_seq = 411
count = 174
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.066559/410, current 156.083099/411: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.083099
last_received_ts = 156.082443
last_seq = 411
current_ts = 156.099640
current_received_ts = 156.099106
current_seq = 412
count = 175
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.083099/411, current 156.099640/412: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.099640
last_received_ts = 156.099106
last_seq = 412
current_ts = 156.116180
current_received_ts = 156.115585
current_seq = 413
count = 176
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.099640/412, current 156.116180/413: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.116180
last_received_ts = 156.115585
last_seq = 413
current_ts = 156.132721
current_received_ts = 156.132172
current_seq = 414
count = 177
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.116180/413, current 156.132721/414: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.132721
last_received_ts = 156.132172
last_seq = 414
current_ts = 156.149277
current_received_ts = 156.148849
current_seq = 415
count = 178
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.132721/414, current 156.149277/415: elapsed=16545.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.149277
last_received_ts = 156.148849
last_seq = 415
current_ts = 156.165817
current_received_ts = 156.165192
current_seq = 416
count = 179
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.149277/415, current 156.165817/416: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.165817
last_received_ts = 156.165192
last_seq = 416
current_ts = 156.182358
current_received_ts = 156.181808
current_seq = 417
count = 180
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.165817/416, current 156.182358/417: elapsed=16545.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.182358
last_received_ts = 156.181808
last_seq = 417
current_ts = 156.198914
current_received_ts = 156.198318
current_seq = 418
count = 181
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.182358/417, current 156.198914/418: elapsed=16547.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.198914
last_received_ts = 156.198318
last_seq = 418
current_ts = 156.215439
current_received_ts = 156.214874
current_seq = 419
count = 182
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.198914/418, current 156.215439/419: elapsed=16538.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.215439
last_received_ts = 156.214874
last_seq = 419
current_ts = 156.231995
current_received_ts = 156.231339
current_seq = 420
count = 183
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.215439/419, current 156.231995/420: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.231995
last_received_ts = 156.231339
last_seq = 420
current_ts = 156.248535
current_received_ts = 156.247971
current_seq = 421
count = 184
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.231995/420, current 156.248535/421: elapsed=16547.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.248535
last_received_ts = 156.247971
last_seq = 421
current_ts = 156.265076
current_received_ts = 156.264359
current_seq = 422
count = 185
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.248535/421, current 156.265076/422: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.265076
last_received_ts = 156.264359
last_seq = 422
current_ts = 156.281631
current_received_ts = 156.281082
current_seq = 423
count = 186
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.265076/422, current 156.281631/423: elapsed=16545.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.281631
last_received_ts = 156.281082
last_seq = 423
current_ts = 156.298172
current_received_ts = 156.297562
current_seq = 424
count = 187
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.281631/423, current 156.298172/424: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.298172
last_received_ts = 156.297562
last_seq = 424
current_ts = 156.314713
current_received_ts = 156.314163
current_seq = 425
count = 188
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.298172/424, current 156.314713/425: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.314713
last_received_ts = 156.314163
last_seq = 425
current_ts = 156.331253
current_received_ts = 156.330673
current_seq = 426
count = 189
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.314713/425, current 156.331253/426: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.331253
last_received_ts = 156.330673
last_seq = 426
current_ts = 156.347794
current_received_ts = 156.347183
current_seq = 427
count = 190
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.331253/426, current 156.347794/427: elapsed=16542.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.347794
last_received_ts = 156.347183
last_seq = 427
current_ts = 156.364349
current_received_ts = 156.363770
current_seq = 428
count = 191
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.347794/427, current 156.364349/428: elapsed=16546.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.364349
last_received_ts = 156.363770
last_seq = 428
current_ts = 156.380890
current_received_ts = 156.380356
current_seq = 429
count = 192
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.364349/428, current 156.380890/429: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.380890
last_received_ts = 156.380356
last_seq = 429
current_ts = 156.397430
current_received_ts = 156.396881
current_seq = 430
count = 193
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.380890/429, current 156.397430/430: elapsed=16544.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.397430
last_received_ts = 156.396881
last_seq = 430
current_ts = 156.413986
current_received_ts = 156.413330
current_seq = 431
count = 194
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.397430/430, current 156.413986/431: elapsed=16547.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.413986
last_received_ts = 156.413330
last_seq = 431
current_ts = 156.430527
current_received_ts = 156.429962
current_seq = 432
count = 195
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.413986/431, current 156.430527/432: elapsed=16540.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.430527
last_received_ts = 156.429962
last_seq = 432
current_ts = 156.447067
current_received_ts = 156.446381
current_seq = 433
count = 196
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.430527/432, current 156.447067/433: elapsed=16549.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.447067
last_received_ts = 156.446381
last_seq = 433
current_ts = 156.463608
current_received_ts = 156.463074
current_seq = 434
count = 197
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.447067/433, current 156.463608/434: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.463608
last_received_ts = 156.463074
last_seq = 434
current_ts = 156.480164
current_received_ts = 156.479553
current_seq = 435
count = 198
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.463608/434, current 156.480164/435: elapsed=16545.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.480164
last_received_ts = 156.479553
last_seq = 435
current_ts = 156.496689
current_received_ts = 156.496140
current_seq = 436
count = 199
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.480164/435, current 156.496689/436: elapsed=16537.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.496689
last_received_ts = 156.496140
last_seq = 436
current_ts = 156.513245
current_received_ts = 156.512634
current_seq = 437
count = 200
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.496689/436, current 156.513245/437: elapsed=16551.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.513245
last_received_ts = 156.512634
last_seq = 437
current_ts = 156.529785
current_received_ts = 156.529175
current_seq = 438
count = 201
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.513245/437, current 156.529785/438: elapsed=16543.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.529785
last_received_ts = 156.529175
last_seq = 438
current_ts = 156.546326
current_received_ts = 156.545761
current_seq = 439
count = 202
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.529785/438, current 156.546326/439: elapsed=16540.0us expected=16488.9us +- 82.4us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.546326
last_received_ts = 156.545761
last_seq = 439
current_ts = 156.562881
current_received_ts = 156.562347
current_seq = 440
count = 203
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.546326/439, current 156.562881/440: elapsed=16550.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.562881
last_received_ts = 156.562347
last_seq = 440
current_ts = 156.579437
current_received_ts = 156.578873
current_seq = 441
count = 204
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.562881/440, current 156.579437/441: elapsed=16556.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.579437
last_received_ts = 156.578873
last_seq = 441
current_ts = 156.595993
current_received_ts = 156.595337
current_seq = 442
count = 205
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.579437/441, current 156.595993/442: elapsed=16566.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.595993
last_received_ts = 156.595337
last_seq = 442
current_ts = 156.612549
current_received_ts = 156.611984
current_seq = 443
count = 206
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.595993/442, current 156.612549/443: elapsed=16553.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.612549
last_received_ts = 156.611984
last_seq = 443
current_ts = 156.629120
current_received_ts = 156.628403
current_seq = 444
count = 207
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.612549/443, current 156.629120/444: elapsed=16563.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.629120
last_received_ts = 156.628403
last_seq = 444
current_ts = 156.645676
current_received_ts = 156.645111
current_seq = 445
count = 208
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.629120/444, current 156.645676/445: elapsed=16553.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.645676
last_received_ts = 156.645111
last_seq = 445
current_ts = 156.662231
current_received_ts = 156.661606
current_seq = 446
count = 209
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.645676/445, current 156.662231/446: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.662231
last_received_ts = 156.661606
last_seq = 446
current_ts = 156.678787
current_received_ts = 156.678253
current_seq = 447
count = 210
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.662231/446, current 156.678787/447: elapsed=16561.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.678787
last_received_ts = 156.678253
last_seq = 447
current_ts = 156.695343
current_received_ts = 156.694778
current_seq = 448
count = 211
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.678787/447, current 156.695343/448: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.695343
last_received_ts = 156.694778
last_seq = 448
current_ts = 156.711899
current_received_ts = 156.711334
current_seq = 449
count = 212
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.695343/448, current 156.711899/449: elapsed=16556.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.711899
last_received_ts = 156.711334
last_seq = 449
current_ts = 156.728455
current_received_ts = 156.727890
current_seq = 450
count = 213
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.711899/449, current 156.728455/450: elapsed=16559.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.728455
last_received_ts = 156.727890
last_seq = 450
current_ts = 156.745010
current_received_ts = 156.744339
current_seq = 451
count = 214
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.728455/450, current 156.745010/451: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.745010
last_received_ts = 156.744339
last_seq = 451
current_ts = 156.761566
current_received_ts = 156.761047
current_seq = 452
count = 215
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.745010/451, current 156.761566/452: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.761566
last_received_ts = 156.761047
last_seq = 452
current_ts = 156.778137
current_received_ts = 156.777542
current_seq = 453
count = 216
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.761566/452, current 156.778137/453: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.778137
last_received_ts = 156.777542
last_seq = 453
current_ts = 156.794693
current_received_ts = 156.794128
current_seq = 454
count = 217
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.778137/453, current 156.794693/454: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.794693
last_received_ts = 156.794128
last_seq = 454
current_ts = 156.811249
current_received_ts = 156.810638
current_seq = 455
count = 218
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.794693/454, current 156.811249/455: elapsed=16564.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.811249
last_received_ts = 156.810638
last_seq = 455
current_ts = 156.827805
current_received_ts = 156.827194
current_seq = 456
count = 219
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.811249/455, current 156.827805/456: elapsed=16553.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.827805
last_received_ts = 156.827194
last_seq = 456
current_ts = 156.844360
current_received_ts = 156.843811
current_seq = 457
count = 220
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.827805/456, current 156.844360/457: elapsed=16556.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.844360
last_received_ts = 156.843811
last_seq = 457
current_ts = 156.860916
current_received_ts = 156.860321
current_seq = 458
count = 221
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.844360/457, current 156.860916/458: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.860916
last_received_ts = 156.860321
last_seq = 458
current_ts = 156.877472
current_received_ts = 156.876907
current_seq = 459
count = 222
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.860916/458, current 156.877472/459: elapsed=16560.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.877472
last_received_ts = 156.876907
last_seq = 459
current_ts = 156.894043
current_received_ts = 156.893326
current_seq = 460
count = 223
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.877472/459, current 156.894043/460: elapsed=16561.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.894043
last_received_ts = 156.893326
last_seq = 460
current_ts = 156.910599
current_received_ts = 156.910049
current_seq = 461
count = 224
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.894043/460, current 156.910599/461: elapsed=16554.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.910599
last_received_ts = 156.910049
last_seq = 461
current_ts = 156.927155
current_received_ts = 156.926529
current_seq = 462
count = 225
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.910599/461, current 156.927155/462: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.927155
last_received_ts = 156.926529
last_seq = 462
current_ts = 156.943710
current_received_ts = 156.943222
current_seq = 463
count = 226
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.927155/462, current 156.943710/463: elapsed=16564.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.943710
last_received_ts = 156.943222
last_seq = 463
current_ts = 156.960266
current_received_ts = 156.959702
current_seq = 464
count = 227
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.943710/463, current 156.960266/464: elapsed=16554.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.960266
last_received_ts = 156.959702
last_seq = 464
current_ts = 156.976822
current_received_ts = 156.976273
current_seq = 465
count = 228
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.960266/464, current 156.976822/465: elapsed=16554.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.976822
last_received_ts = 156.976273
last_seq = 465
current_ts = 156.993378
current_received_ts = 156.992828
current_seq = 466
count = 229
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.976822/465, current 156.993378/466: elapsed=16560.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 156.993378
last_received_ts = 156.992828
last_seq = 466
current_ts = 157.009949
current_received_ts = 157.009338
current_seq = 467
count = 230
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 156.993378/466, current 157.009949/467: elapsed=16564.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.009949
last_received_ts = 157.009338
last_seq = 467
current_ts = 157.026505
current_received_ts = 157.025940
current_seq = 468
count = 231
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.009949/467, current 157.026505/468: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.026505
last_received_ts = 157.025940
last_seq = 468
current_ts = 157.043060
current_received_ts = 157.042450
current_seq = 469
count = 232
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.026505/468, current 157.043060/469: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.043060
last_received_ts = 157.042450
last_seq = 469
current_ts = 157.059616
current_received_ts = 157.059097
current_seq = 470
count = 233
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.043060/469, current 157.059616/470: elapsed=16562.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.059616
last_received_ts = 157.059097
last_seq = 470
current_ts = 157.076172
current_received_ts = 157.075623
current_seq = 471
count = 234
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.059616/470, current 157.076172/471: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.076172
last_received_ts = 157.075623
last_seq = 471
current_ts = 157.092743
current_received_ts = 157.092194
current_seq = 472
count = 235
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.076172/471, current 157.092743/472: elapsed=16560.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.092743
last_received_ts = 157.092194
last_seq = 472
current_ts = 157.109283
current_received_ts = 157.108902
current_seq = 473
count = 236
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.092743/472, current 157.109283/473: elapsed=16551.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.109283
last_received_ts = 157.108902
last_seq = 473
current_ts = 157.125854
current_received_ts = 157.125198
current_seq = 474
count = 237
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.109283/473, current 157.125854/474: elapsed=16559.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.125854
last_received_ts = 157.125198
last_seq = 474
current_ts = 157.142410
current_received_ts = 157.142059
current_seq = 475
count = 238
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.125854/474, current 157.142410/475: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.142410
last_received_ts = 157.142059
last_seq = 475
current_ts = 157.158966
current_received_ts = 157.158371
current_seq = 476
count = 239
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.142410/475, current 157.158966/476: elapsed=16563.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.158966
last_received_ts = 157.158371
last_seq = 476
current_ts = 157.175522
current_received_ts = 157.174988
current_seq = 477
count = 240
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.158966/476, current 157.175522/477: elapsed=16554.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.175522
last_received_ts = 157.174988
last_seq = 477
current_ts = 157.192078
current_received_ts = 157.191452
current_seq = 478
count = 241
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.175522/477, current 157.192078/478: elapsed=16560.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.192078
last_received_ts = 157.191452
last_seq = 478
current_ts = 157.208633
current_received_ts = 157.208084
current_seq = 479
count = 242
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.192078/478, current 157.208633/479: elapsed=16556.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.208633
last_received_ts = 157.208084
last_seq = 479
current_ts = 157.225189
current_received_ts = 157.224640
current_seq = 480
count = 243
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.208633/479, current 157.225189/480: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.225189
last_received_ts = 157.224640
last_seq = 480
current_ts = 157.241760
current_received_ts = 157.241211
current_seq = 481
count = 244
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.225189/480, current 157.241760/481: elapsed=16562.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.241760
last_received_ts = 157.241211
last_seq = 481
current_ts = 157.258316
current_received_ts = 157.257751
current_seq = 482
count = 245
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.241760/481, current 157.258316/482: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.258316
last_received_ts = 157.257751
last_seq = 482
current_ts = 157.274872
current_received_ts = 157.274200
current_seq = 483
count = 246
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.258316/482, current 157.274872/483: elapsed=16556.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.274872
last_received_ts = 157.274200
last_seq = 483
current_ts = 157.291428
current_received_ts = 157.290878
current_seq = 484
count = 247
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.274872/483, current 157.291428/484: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.291428
last_received_ts = 157.290878
last_seq = 484
current_ts = 157.307983
current_received_ts = 157.307587
current_seq = 485
count = 248
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.291428/484, current 157.307983/485: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.307983
last_received_ts = 157.307587
last_seq = 485
current_ts = 157.324539
current_received_ts = 157.323975
current_seq = 486
count = 249
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.307983/485, current 157.324539/486: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.324539
last_received_ts = 157.323975
last_seq = 486
current_ts = 157.341110
current_received_ts = 157.340515
current_seq = 487
count = 250
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.324539/486, current 157.341110/487: elapsed=16559.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.341110
last_received_ts = 157.340515
last_seq = 487
current_ts = 157.357666
current_received_ts = 157.357101
current_seq = 488
count = 251
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.341110/487, current 157.357666/488: elapsed=16562.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.357666
last_received_ts = 157.357101
last_seq = 488
current_ts = 157.374222
current_received_ts = 157.373795
current_seq = 489
count = 252
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.357666/488, current 157.374222/489: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.374222
last_received_ts = 157.373795
last_seq = 489
current_ts = 157.390778
current_received_ts = 157.390182
current_seq = 490
count = 253
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.374222/489, current 157.390778/490: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.390778
last_received_ts = 157.390182
last_seq = 490
current_ts = 157.407333
current_received_ts = 157.406769
current_seq = 491
count = 254
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.390778/490, current 157.407333/491: elapsed=16560.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.407333
last_received_ts = 157.406769
last_seq = 491
current_ts = 157.423889
current_received_ts = 157.423309
current_seq = 492
count = 255
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.407333/491, current 157.423889/492: elapsed=16557.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.423889
last_received_ts = 157.423309
last_seq = 492
current_ts = 157.440445
current_received_ts = 157.439880
current_seq = 493
count = 256
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.423889/492, current 157.440445/493: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.440445
last_received_ts = 157.439880
last_seq = 493
current_ts = 157.457016
current_received_ts = 157.456421
current_seq = 494
count = 257
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.440445/493, current 157.457016/494: elapsed=16562.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.457016
last_received_ts = 157.456421
last_seq = 494
current_ts = 157.473572
current_received_ts = 157.473053
current_seq = 495
count = 258
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.457016/494, current 157.473572/495: elapsed=16555.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.473572
last_received_ts = 157.473053
last_seq = 495
current_ts = 157.490128
current_received_ts = 157.489578
current_seq = 496
count = 259
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.473572/495, current 157.490128/496: elapsed=16554.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.490128
last_received_ts = 157.489578
last_seq = 496
current_ts = 157.506683
current_received_ts = 157.506134
current_seq = 497
count = 260
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.490128/496, current 157.506683/497: elapsed=16559.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.506683
last_received_ts = 157.506134
last_seq = 497
current_ts = 157.523239
current_received_ts = 157.522675
current_seq = 498
count = 261
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.506683/497, current 157.523239/498: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.523239
last_received_ts = 157.522675
last_seq = 498
current_ts = 157.539795
current_received_ts = 157.539215
current_seq = 499
count = 262
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.523239/498, current 157.539795/499: elapsed=16558.0us expected=16488.9us +- 82.4us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.539795
last_received_ts = 157.539215
last_seq = 499
current_ts = 157.556366
current_received_ts = 157.555801
current_seq = 500
count = 263
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.539795/499, current 157.556366/500: elapsed=16565.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.556366
last_received_ts = 157.555801
last_seq = 500
current_ts = 157.572922
current_received_ts = 157.572327
current_seq = 501
count = 264
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.556366/500, current 157.572922/501: elapsed=16568.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.572922
last_received_ts = 157.572327
last_seq = 501
current_ts = 157.589493
current_received_ts = 157.588928
current_seq = 502
count = 265
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.572922/501, current 157.589493/502: elapsed=16568.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: name = flip
last_ts = 157.589493
last_received_ts = 157.588928
last_seq = 502
current_ts = 157.606064
current_received_ts = 157.605652
current_seq = 503
count = 266
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 157.589493/502, current 157.606064/503: elapsed=16573.0us expected=16488.9us +- 82.4us, error 0.5%
(kms_flip:2809) DEBUG: inconsistent flip ts/seq: last 157.589493/502, current 157.606064/503: elapsed=16573.0us expected=16488.9us
(kms_flip:2809) DEBUG: expected 67995, counted 266, encoder type 2
(kms_flip:2809) DEBUG: dropped frames, expected 67995, counted 266, encoder type 2
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2809) igt_core-INFO: Stack trace:
(kms_flip:2809) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2809) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2809) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2809) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2809) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2809) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2809) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2809) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.304s)
Starting dynamic subtest: C-eDP1
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.368073
last_received_ts = 170.367447
last_seq = 732
current_ts = 170.384735
current_received_ts = 170.384201
current_seq = 733
count = 480
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.368073/732, current 170.384735/733: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.384735
last_received_ts = 170.384201
last_seq = 733
current_ts = 170.401413
current_received_ts = 170.400848
current_seq = 734
count = 481
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.384735/733, current 170.401413/734: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.401413
last_received_ts = 170.400848
last_seq = 734
current_ts = 170.418076
current_received_ts = 170.417465
current_seq = 735
count = 482
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.401413/734, current 170.418076/735: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.418076
last_received_ts = 170.417465
last_seq = 735
current_ts = 170.434753
current_received_ts = 170.434204
current_seq = 736
count = 483
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.418076/735, current 170.434753/736: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.434753
last_received_ts = 170.434204
last_seq = 736
current_ts = 170.451416
current_received_ts = 170.450760
current_seq = 737
count = 484
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.434753/736, current 170.451416/737: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.451416
last_received_ts = 170.450760
last_seq = 737
current_ts = 170.468094
current_received_ts = 170.467377
current_seq = 738
count = 485
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.451416/737, current 170.468094/738: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.468094
last_received_ts = 170.467377
last_seq = 738
current_ts = 170.484756
current_received_ts = 170.484100
current_seq = 739
count = 486
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.468094/738, current 170.484756/739: elapsed=16676.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.484756
last_received_ts = 170.484100
last_seq = 739
current_ts = 170.501434
current_received_ts = 170.500763
current_seq = 740
count = 487
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.484756/739, current 170.501434/740: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.501434
last_received_ts = 170.500763
last_seq = 740
current_ts = 170.518112
current_received_ts = 170.517380
current_seq = 741
count = 488
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.501434/740, current 170.518112/741: elapsed=16678.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.518112
last_received_ts = 170.517380
last_seq = 741
current_ts = 170.534775
current_received_ts = 170.534119
current_seq = 742
count = 489
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.518112/741, current 170.534775/742: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.534775
last_received_ts = 170.534119
last_seq = 742
current_ts = 170.551453
current_received_ts = 170.550766
current_seq = 743
count = 490
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.534775/742, current 170.551453/743: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.551453
last_received_ts = 170.550766
last_seq = 743
current_ts = 170.568115
current_received_ts = 170.567444
current_seq = 744
count = 491
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.551453/743, current 170.568115/744: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.568115
last_received_ts = 170.567444
last_seq = 744
current_ts = 170.584778
current_received_ts = 170.584122
current_seq = 745
count = 492
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.568115/744, current 170.584778/745: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.584778
last_received_ts = 170.584122
last_seq = 745
current_ts = 170.601456
current_received_ts = 170.600784
current_seq = 746
count = 493
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.584778/745, current 170.601456/746: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.601456
last_received_ts = 170.600784
last_seq = 746
current_ts = 170.618118
current_received_ts = 170.617401
current_seq = 747
count = 494
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.601456/746, current 170.618118/747: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.618118
last_received_ts = 170.617401
last_seq = 747
current_ts = 170.634796
current_received_ts = 170.634140
current_seq = 748
count = 495
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.618118/747, current 170.634796/748: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.634796
last_received_ts = 170.634140
last_seq = 748
current_ts = 170.651474
current_received_ts = 170.650803
current_seq = 749
count = 496
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.634796/748, current 170.651474/749: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.651474
last_received_ts = 170.650803
last_seq = 749
current_ts = 170.668137
current_received_ts = 170.667465
current_seq = 750
count = 497
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.651474/749, current 170.668137/750: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.668137
last_received_ts = 170.667465
last_seq = 750
current_ts = 170.684814
current_received_ts = 170.684143
current_seq = 751
count = 498
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.668137/750, current 170.684814/751: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.684814
last_received_ts = 170.684143
last_seq = 751
current_ts = 170.701477
current_received_ts = 170.700806
current_seq = 752
count = 499
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.684814/751, current 170.701477/752: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.701477
last_received_ts = 170.700806
last_seq = 752
current_ts = 170.718155
current_received_ts = 170.717422
current_seq = 753
count = 500
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.701477/752, current 170.718155/753: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.718155
last_received_ts = 170.717422
last_seq = 753
current_ts = 170.734818
current_received_ts = 170.734146
current_seq = 754
count = 501
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.718155/753, current 170.734818/754: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.734818
last_received_ts = 170.734146
last_seq = 754
current_ts = 170.751480
current_received_ts = 170.750824
current_seq = 755
count = 502
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.734818/754, current 170.751480/755: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.751480
last_received_ts = 170.750824
last_seq = 755
current_ts = 170.768158
current_received_ts = 170.767685
current_seq = 756
count = 503
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.751480/755, current 170.768158/756: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.768158
last_received_ts = 170.767685
last_seq = 756
current_ts = 170.784836
current_received_ts = 170.784195
current_seq = 757
count = 504
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.768158/756, current 170.784836/757: elapsed=16677.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.784836
last_received_ts = 170.784195
last_seq = 757
current_ts = 170.801498
current_received_ts = 170.800842
current_seq = 758
count = 505
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.784836/757, current 170.801498/758: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.801498
last_received_ts = 170.800842
last_seq = 758
current_ts = 170.818176
current_received_ts = 170.817459
current_seq = 759
count = 506
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.801498/758, current 170.818176/759: elapsed=16667.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.818176
last_received_ts = 170.817459
last_seq = 759
current_ts = 170.834839
current_received_ts = 170.834183
current_seq = 760
count = 507
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.818176/759, current 170.834839/760: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.834839
last_received_ts = 170.834183
last_seq = 760
current_ts = 170.851517
current_received_ts = 170.850845
current_seq = 761
count = 508
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.834839/760, current 170.851517/761: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.851517
last_received_ts = 170.850845
last_seq = 761
current_ts = 170.868179
current_received_ts = 170.867508
current_seq = 762
count = 509
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.851517/761, current 170.868179/762: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.868179
last_received_ts = 170.867508
last_seq = 762
current_ts = 170.884857
current_received_ts = 170.884186
current_seq = 763
count = 510
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.868179/762, current 170.884857/763: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.884857
last_received_ts = 170.884186
last_seq = 763
current_ts = 170.901520
current_received_ts = 170.900848
current_seq = 764
count = 511
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.884857/763, current 170.901520/764: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.901520
last_received_ts = 170.900848
last_seq = 764
current_ts = 170.918198
current_received_ts = 170.917526
current_seq = 765
count = 512
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.901520/764, current 170.918198/765: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.918198
last_received_ts = 170.917526
last_seq = 765
current_ts = 170.934860
current_received_ts = 170.934204
current_seq = 766
count = 513
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.918198/765, current 170.934860/766: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.934860
last_received_ts = 170.934204
last_seq = 766
current_ts = 170.951538
current_received_ts = 170.950867
current_seq = 767
count = 514
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.934860/766, current 170.951538/767: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.951538
last_received_ts = 170.950867
last_seq = 767
current_ts = 170.968201
current_received_ts = 170.967529
current_seq = 768
count = 515
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.951538/767, current 170.968201/768: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.968201
last_received_ts = 170.967529
last_seq = 768
current_ts = 170.984879
current_received_ts = 170.984207
current_seq = 769
count = 516
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.968201/768, current 170.984879/769: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 170.984879
last_received_ts = 170.984207
last_seq = 769
current_ts = 171.001541
current_received_ts = 171.001068
current_seq = 770
count = 517
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 170.984879/769, current 171.001541/770: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.001541
last_received_ts = 171.001068
last_seq = 770
current_ts = 171.018219
current_received_ts = 171.017548
current_seq = 771
count = 518
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.001541/770, current 171.018219/771: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.018219
last_received_ts = 171.017548
last_seq = 771
current_ts = 171.034882
current_received_ts = 171.034225
current_seq = 772
count = 519
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.018219/771, current 171.034882/772: elapsed=16663.0us expected=16605.8us +- 83.0us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.034882
last_received_ts = 171.034225
last_seq = 772
current_ts = 171.051544
current_received_ts = 171.050903
current_seq = 773
count = 520
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.034882/772, current 171.051544/773: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.051544
last_received_ts = 171.050903
last_seq = 773
current_ts = 171.068222
current_received_ts = 171.067551
current_seq = 774
count = 521
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.051544/773, current 171.068222/774: elapsed=16677.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.068222
last_received_ts = 171.067551
last_seq = 774
current_ts = 171.084900
current_received_ts = 171.084106
current_seq = 775
count = 522
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.068222/774, current 171.084900/775: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.084900
last_received_ts = 171.084106
last_seq = 775
current_ts = 171.101562
current_received_ts = 171.100891
current_seq = 776
count = 523
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.084900/775, current 171.101562/776: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.101562
last_received_ts = 171.100891
last_seq = 776
current_ts = 171.118240
current_received_ts = 171.117523
current_seq = 777
count = 524
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.101562/776, current 171.118240/777: elapsed=16676.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.118240
last_received_ts = 171.117523
last_seq = 777
current_ts = 171.134903
current_received_ts = 171.134247
current_seq = 778
count = 525
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.118240/777, current 171.134903/778: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.134903
last_received_ts = 171.134247
last_seq = 778
current_ts = 171.151581
current_received_ts = 171.150909
current_seq = 779
count = 526
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.134903/778, current 171.151581/779: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.151581
last_received_ts = 171.150909
last_seq = 779
current_ts = 171.168243
current_received_ts = 171.167496
current_seq = 780
count = 527
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.151581/779, current 171.168243/780: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.168243
last_received_ts = 171.167496
last_seq = 780
current_ts = 171.184921
current_received_ts = 171.184250
current_seq = 781
count = 528
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.168243/780, current 171.184921/781: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.184921
last_received_ts = 171.184250
last_seq = 781
current_ts = 171.201584
current_received_ts = 171.200912
current_seq = 782
count = 529
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.184921/781, current 171.201584/782: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.201584
last_received_ts = 171.200912
last_seq = 782
current_ts = 171.218262
current_received_ts = 171.217575
current_seq = 783
count = 530
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.201584/782, current 171.218262/783: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.218262
last_received_ts = 171.217575
last_seq = 783
current_ts = 171.234924
current_received_ts = 171.234253
current_seq = 784
count = 531
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.218262/783, current 171.234924/784: elapsed=16662.0us expected=16605.8us +- 83.0us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.234924
last_received_ts = 171.234253
last_seq = 784
current_ts = 171.251587
current_received_ts = 171.250931
current_seq = 785
count = 532
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.234924/784, current 171.251587/785: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.251587
last_received_ts = 171.250931
last_seq = 785
current_ts = 171.268265
current_received_ts = 171.267593
current_seq = 786
count = 533
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.251587/785, current 171.268265/786: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.268265
last_received_ts = 171.267593
last_seq = 786
current_ts = 171.284943
current_received_ts = 171.284256
current_seq = 787
count = 534
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.268265/786, current 171.284943/787: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.284943
last_received_ts = 171.284256
last_seq = 787
current_ts = 171.301605
current_received_ts = 171.300919
current_seq = 788
count = 535
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.284943/787, current 171.301605/788: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.301605
last_received_ts = 171.300919
last_seq = 788
current_ts = 171.318283
current_received_ts = 171.317551
current_seq = 789
count = 536
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.301605/788, current 171.318283/789: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.318283
last_received_ts = 171.317551
last_seq = 789
current_ts = 171.334946
current_received_ts = 171.334244
current_seq = 790
count = 537
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.318283/789, current 171.334946/790: elapsed=16667.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.334946
last_received_ts = 171.334244
last_seq = 790
current_ts = 171.351608
current_received_ts = 171.350967
current_seq = 791
count = 538
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.334946/790, current 171.351608/791: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.351608
last_received_ts = 171.350967
last_seq = 791
current_ts = 171.368286
current_received_ts = 171.367844
current_seq = 792
count = 539
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.351608/791, current 171.368286/792: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.368286
last_received_ts = 171.367844
last_seq = 792
current_ts = 171.384964
current_received_ts = 171.384247
current_seq = 793
count = 540
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.368286/792, current 171.384964/793: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.384964
last_received_ts = 171.384247
last_seq = 793
current_ts = 171.401627
current_received_ts = 171.400955
current_seq = 794
count = 541
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.384964/793, current 171.401627/794: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.401627
last_received_ts = 171.400955
last_seq = 794
current_ts = 171.418289
current_received_ts = 171.417603
current_seq = 795
count = 542
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.401627/794, current 171.418289/795: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.418289
last_received_ts = 171.417603
last_seq = 795
current_ts = 171.434967
current_received_ts = 171.434250
current_seq = 796
count = 543
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.418289/795, current 171.434967/796: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.434967
last_received_ts = 171.434250
last_seq = 796
current_ts = 171.451645
current_received_ts = 171.451157
current_seq = 797
count = 544
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.434967/796, current 171.451645/797: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.451645
last_received_ts = 171.451157
last_seq = 797
current_ts = 171.468307
current_received_ts = 171.467636
current_seq = 798
count = 545
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.451645/797, current 171.468307/798: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.468307
last_received_ts = 171.467636
last_seq = 798
current_ts = 171.484985
current_received_ts = 171.484283
current_seq = 799
count = 546
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.468307/798, current 171.484985/799: elapsed=16667.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.484985
last_received_ts = 171.484283
last_seq = 799
current_ts = 171.501648
current_received_ts = 171.500992
current_seq = 800
count = 547
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.484985/799, current 171.501648/800: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.501648
last_received_ts = 171.500992
last_seq = 800
current_ts = 171.518326
current_received_ts = 171.517654
current_seq = 801
count = 548
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.501648/800, current 171.518326/801: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.518326
last_received_ts = 171.517654
last_seq = 801
current_ts = 171.534988
current_received_ts = 171.534302
current_seq = 802
count = 549
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.518326/801, current 171.534988/802: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.534988
last_received_ts = 171.534302
last_seq = 802
current_ts = 171.551666
current_received_ts = 171.550995
current_seq = 803
count = 550
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.534988/802, current 171.551666/803: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.551666
last_received_ts = 171.550995
last_seq = 803
current_ts = 171.568329
current_received_ts = 171.567657
current_seq = 804
count = 551
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.551666/803, current 171.568329/804: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.568329
last_received_ts = 171.567657
last_seq = 804
current_ts = 171.585007
current_received_ts = 171.584320
current_seq = 805
count = 552
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.568329/804, current 171.585007/805: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.585007
last_received_ts = 171.584320
last_seq = 805
current_ts = 171.601669
current_received_ts = 171.601028
current_seq = 806
count = 553
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.585007/805, current 171.601669/806: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.601669
last_received_ts = 171.601028
last_seq = 806
current_ts = 171.618347
current_received_ts = 171.617661
current_seq = 807
count = 554
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.601669/806, current 171.618347/807: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.618347
last_received_ts = 171.617661
last_seq = 807
current_ts = 171.635010
current_received_ts = 171.634262
current_seq = 808
count = 555
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.618347/807, current 171.635010/808: elapsed=16664.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.635010
last_received_ts = 171.634262
last_seq = 808
current_ts = 171.651688
current_received_ts = 171.651031
current_seq = 809
count = 556
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.635010/808, current 171.651688/809: elapsed=16676.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.651688
last_received_ts = 171.651031
last_seq = 809
current_ts = 171.668350
current_received_ts = 171.667664
current_seq = 810
count = 557
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.651688/809, current 171.668350/810: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.668350
last_received_ts = 171.667664
last_seq = 810
current_ts = 171.685028
current_received_ts = 171.684280
current_seq = 811
count = 558
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.668350/810, current 171.685028/811: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.685028
last_received_ts = 171.684280
last_seq = 811
current_ts = 171.701691
current_received_ts = 171.701035
current_seq = 812
count = 559
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.685028/811, current 171.701691/812: elapsed=16663.0us expected=16605.8us +- 83.0us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.701691
last_received_ts = 171.701035
last_seq = 812
current_ts = 171.718369
current_received_ts = 171.717865
current_seq = 813
count = 560
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.701691/812, current 171.718369/813: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.718369
last_received_ts = 171.717865
last_seq = 813
current_ts = 171.735031
current_received_ts = 171.734268
current_seq = 814
count = 561
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.718369/813, current 171.735031/814: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.735031
last_received_ts = 171.734268
last_seq = 814
current_ts = 171.751694
current_received_ts = 171.751068
current_seq = 815
count = 562
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.735031/814, current 171.751694/815: elapsed=16663.0us expected=16605.8us +- 83.0us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.751694
last_received_ts = 171.751068
last_seq = 815
current_ts = 171.768372
current_received_ts = 171.767685
current_seq = 816
count = 563
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.751694/815, current 171.768372/816: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.768372
last_received_ts = 171.767685
last_seq = 816
current_ts = 171.785034
current_received_ts = 171.784348
current_seq = 817
count = 564
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.768372/816, current 171.785034/817: elapsed=16676.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.785034
last_received_ts = 171.784348
last_seq = 817
current_ts = 171.801697
current_received_ts = 171.801056
current_seq = 818
count = 565
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.785034/817, current 171.801697/818: elapsed=16664.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.801697
last_received_ts = 171.801056
last_seq = 818
current_ts = 171.818375
current_received_ts = 171.817703
current_seq = 819
count = 566
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.801697/818, current 171.818375/819: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.818375
last_received_ts = 171.817703
last_seq = 819
current_ts = 171.835052
current_received_ts = 171.834351
current_seq = 820
count = 567
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.818375/819, current 171.835052/820: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.835052
last_received_ts = 171.834351
last_seq = 820
current_ts = 171.851715
current_received_ts = 171.851257
current_seq = 821
count = 568
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.835052/820, current 171.851715/821: elapsed=16665.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.851715
last_received_ts = 171.851257
last_seq = 821
current_ts = 171.868378
current_received_ts = 171.867706
current_seq = 822
count = 569
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.851715/821, current 171.868378/822: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.868378
last_received_ts = 171.867706
last_seq = 822
current_ts = 171.885056
current_received_ts = 171.884369
current_seq = 823
count = 570
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.868378/822, current 171.885056/823: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.885056
last_received_ts = 171.884369
last_seq = 823
current_ts = 171.901718
current_received_ts = 171.901077
current_seq = 824
count = 571
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.885056/823, current 171.901718/824: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.901718
last_received_ts = 171.901077
last_seq = 824
current_ts = 171.918396
current_received_ts = 171.917740
current_seq = 825
count = 572
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.901718/824, current 171.918396/825: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.918396
last_received_ts = 171.917740
last_seq = 825
current_ts = 171.935059
current_received_ts = 171.934372
current_seq = 826
count = 573
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.918396/825, current 171.935059/826: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.935059
last_received_ts = 171.934372
last_seq = 826
current_ts = 171.951736
current_received_ts = 171.951065
current_seq = 827
count = 574
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.935059/826, current 171.951736/827: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.951736
last_received_ts = 171.951065
last_seq = 827
current_ts = 171.968399
current_received_ts = 171.967728
current_seq = 828
count = 575
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.951736/827, current 171.968399/828: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.968399
last_received_ts = 171.967728
last_seq = 828
current_ts = 171.985077
current_received_ts = 171.984360
current_seq = 829
count = 576
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.968399/828, current 171.985077/829: elapsed=16671.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 171.985077
last_received_ts = 171.984360
last_seq = 829
current_ts = 172.001740
current_received_ts = 172.001068
current_seq = 830
count = 577
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 171.985077/829, current 172.001740/830: elapsed=16665.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.001740
last_received_ts = 172.001068
last_seq = 830
current_ts = 172.018402
current_received_ts = 172.017761
current_seq = 831
count = 578
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.001740/830, current 172.018402/831: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.018402
last_received_ts = 172.017761
last_seq = 831
current_ts = 172.035080
current_received_ts = 172.034317
current_seq = 832
count = 579
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.018402/831, current 172.035080/832: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.035080
last_received_ts = 172.034317
last_seq = 832
current_ts = 172.051743
current_received_ts = 172.051086
current_seq = 833
count = 580
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.035080/832, current 172.051743/833: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.051743
last_received_ts = 172.051086
last_seq = 833
current_ts = 172.068420
current_received_ts = 172.067749
current_seq = 834
count = 581
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.051743/833, current 172.068420/834: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.068420
last_received_ts = 172.067749
last_seq = 834
current_ts = 172.085083
current_received_ts = 172.084305
current_seq = 835
count = 582
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.068420/834, current 172.085083/835: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.085083
last_received_ts = 172.084305
last_seq = 835
current_ts = 172.101761
current_received_ts = 172.101089
current_seq = 836
count = 583
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.085083/835, current 172.101761/836: elapsed=16675.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.101761
last_received_ts = 172.101089
last_seq = 836
current_ts = 172.118423
current_received_ts = 172.117752
current_seq = 837
count = 584
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.101761/836, current 172.118423/837: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.118423
last_received_ts = 172.117752
last_seq = 837
current_ts = 172.135101
current_received_ts = 172.134583
current_seq = 838
count = 585
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.118423/837, current 172.135101/838: elapsed=16668.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.135101
last_received_ts = 172.134583
last_seq = 838
current_ts = 172.151764
current_received_ts = 172.151108
current_seq = 839
count = 586
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.135101/838, current 172.151764/839: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.151764
last_received_ts = 172.151108
last_seq = 839
current_ts = 172.168427
current_received_ts = 172.167770
current_seq = 840
count = 587
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.151764/839, current 172.168427/840: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.168427
last_received_ts = 172.167770
last_seq = 840
current_ts = 172.185104
current_received_ts = 172.184418
current_seq = 841
count = 588
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.168427/840, current 172.185104/841: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.185104
last_received_ts = 172.184418
last_seq = 841
current_ts = 172.201767
current_received_ts = 172.201126
current_seq = 842
count = 589
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.185104/841, current 172.201767/842: elapsed=16666.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.201767
last_received_ts = 172.201126
last_seq = 842
current_ts = 172.218445
current_received_ts = 172.217773
current_seq = 843
count = 590
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.201767/842, current 172.218445/843: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.218445
last_received_ts = 172.217773
last_seq = 843
current_ts = 172.235107
current_received_ts = 172.234390
current_seq = 844
count = 591
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.218445/843, current 172.235107/844: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.235107
last_received_ts = 172.234390
last_seq = 844
current_ts = 172.251785
current_received_ts = 172.251114
current_seq = 845
count = 592
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.235107/844, current 172.251785/845: elapsed=16665.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.251785
last_received_ts = 172.251114
last_seq = 845
current_ts = 172.268448
current_received_ts = 172.267776
current_seq = 846
count = 593
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.251785/845, current 172.268448/846: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.268448
last_received_ts = 172.267776
last_seq = 846
current_ts = 172.285126
current_received_ts = 172.284393
current_seq = 847
count = 594
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.268448/846, current 172.285126/847: elapsed=16670.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.285126
last_received_ts = 172.284393
last_seq = 847
current_ts = 172.301788
current_received_ts = 172.301117
current_seq = 848
count = 595
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.285126/847, current 172.301788/848: elapsed=16663.0us expected=16605.8us +- 83.0us, error 0.3%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.301788
last_received_ts = 172.301117
last_seq = 848
current_ts = 172.318466
current_received_ts = 172.317795
current_seq = 849
count = 596
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.301788/848, current 172.318466/849: elapsed=16673.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.318466
last_received_ts = 172.317795
last_seq = 849
current_ts = 172.335129
current_received_ts = 172.334396
current_seq = 850
count = 597
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.318466/849, current 172.335129/850: elapsed=16672.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.335129
last_received_ts = 172.334396
last_seq = 850
current_ts = 172.351791
current_received_ts = 172.351135
current_seq = 851
count = 598
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.335129/850, current 172.351791/851: elapsed=16664.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.351791
last_received_ts = 172.351135
last_seq = 851
current_ts = 172.368469
current_received_ts = 172.367798
current_seq = 852
count = 599
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.351791/851, current 172.368469/852: elapsed=16669.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: name = flip
last_ts = 172.368469
last_received_ts = 172.367798
last_seq = 852
current_ts = 172.385132
current_received_ts = 172.384415
current_seq = 853
count = 600
seq_step = 1
(kms_flip:2809) DEBUG: flip ts/seq: last 172.368469/852, current 172.385132/853: elapsed=16674.0us expected=16605.8us +- 83.0us, error 0.4%
(kms_flip:2809) DEBUG: expected 602, counted 601, encoder type 2
(kms_flip:2809) DEBUG: dropped frames, expected 602, counted 601, encoder type 2
(kms_flip:2809) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2809) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2809) igt_core-INFO: Stack trace:
(kms_flip:2809) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2809) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2809) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2809) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2809) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2809) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2809) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2809) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (14.727s)
Subtest plain-flip-ts-check: FAIL (29.853s)
(kms_flip:2809) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2809) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2809) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2809) igt_kms-CRITICAL: DPMS property not found on 189