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

shard-dg2-432

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

Using IGT_SRANDOM=1741422749 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17141.5us +- 7.276us accuracy 0.13%
vblank interval differs from modeline! expected 16666.7us, measured 17142us +- 7.276us, difference 474.8us (65.3 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 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (4.818s)
Starting dynamic subtest: B-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16914.8us +- 6.327us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16915us +- 6.327us, difference 248.1us (39.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 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A2: FAIL (6.266s)
Starting dynamic subtest: C-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16782.4us +- 8.382us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 16782us +- 8.382us, difference 115.8us (13.8 sigma)
Dynamic subtest C-HDMI-A2: SUCCESS (4.222s)
Starting dynamic subtest: D-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16733.9us +- 8.536us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 16734us +- 8.536us, difference 67.3us (7.9 sigma)
Dynamic subtest D-HDMI-A2: SUCCESS (4.248s)
Starting dynamic subtest: A-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16708.2us +- 4.597us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16708us +- 4.597us, difference 41.6us (9.0 sigma)
Dynamic subtest A-DP2: SUCCESS (4.295s)
Starting dynamic subtest: B-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16694.6us +- 5.464us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16695us +- 5.464us, difference 28.0us (5.1 sigma)
Dynamic subtest B-DP2: SUCCESS (4.272s)
Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16693.1us +- 5.615us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16693us +- 5.615us, difference 26.4us (4.7 sigma)
Dynamic subtest C-DP2: SUCCESS (4.265s)
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16688.1us +- 6.879us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16688us +- 6.879us, difference 21.5us (3.1 sigma)
Dynamic subtest D-DP2: SUCCESS (4.258s)
Subtest plain-flip-ts-check: FAIL (36.668s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
(kms_flip:3861) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3861) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3861) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3861) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3861) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3861) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3861) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3861) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3861) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bc2a80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bc2a80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bcfe70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bcfe70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bd41b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bd41b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bcee00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) intel_allocator_simple-DEBUG: <ial: 0x5729a9bcee00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3861) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3861) DEBUG: No stale events found
(kms_flip:3861) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3861) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3861) INFO: Expected frametime: 16667us; measured 17141.5us +- 7.276us accuracy 0.13%
(kms_flip:3861) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17142us +- 7.276us, difference 474.8us (65.3 sigma)
(kms_flip:3861) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 173.568497
current_received_ts = 173.568100
current_seq = 5618
count = 0
seq_step = 1
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.568497
last_received_ts = 173.568100
last_seq = 5618
current_ts = 173.585632
current_received_ts = 173.585220
current_seq = 5619
count = 1
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.568497/5618, current 173.585632/5619: elapsed=17139.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.585632
last_received_ts = 173.585220
last_seq = 5619
current_ts = 173.602768
current_received_ts = 173.602234
current_seq = 5620
count = 2
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.585632/5619, current 173.602768/5620: elapsed=17137.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.602768
last_received_ts = 173.602234
last_seq = 5620
current_ts = 173.619919
current_received_ts = 173.619385
current_seq = 5621
count = 3
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.602768/5620, current 173.619919/5621: elapsed=17146.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.619919
last_received_ts = 173.619385
last_seq = 5621
current_ts = 173.637054
current_received_ts = 173.636597
current_seq = 5622
count = 4
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.619919/5621, current 173.637054/5622: elapsed=17144.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.637054
last_received_ts = 173.636597
last_seq = 5622
current_ts = 173.654205
current_received_ts = 173.653656
current_seq = 5623
count = 5
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.637054/5622, current 173.654205/5623: elapsed=17142.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.654205
last_received_ts = 173.653656
last_seq = 5623
current_ts = 173.671341
current_received_ts = 173.670898
current_seq = 5624
count = 6
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.654205/5623, current 173.671341/5624: elapsed=17140.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.671341
last_received_ts = 173.670898
last_seq = 5624
current_ts = 173.688477
current_received_ts = 173.687943
current_seq = 5625
count = 7
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.671341/5624, current 173.688477/5625: elapsed=17138.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.688477
last_received_ts = 173.687943
last_seq = 5625
current_ts = 173.705612
current_received_ts = 173.705109
current_seq = 5626
count = 8
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.688477/5625, current 173.705612/5626: elapsed=17137.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.705612
last_received_ts = 173.705109
last_seq = 5626
current_ts = 173.722763
current_received_ts = 173.722305
current_seq = 5627
count = 9
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.705612/5626, current 173.722763/5627: elapsed=17140.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.722763
last_received_ts = 173.722305
last_seq = 5627
current_ts = 173.739899
current_received_ts = 173.739365
current_seq = 5628
count = 10
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.722763/5627, current 173.739899/5628: elapsed=17147.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.739899
last_received_ts = 173.739365
last_seq = 5628
current_ts = 173.757034
current_received_ts = 173.756439
current_seq = 5629
count = 11
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.739899/5628, current 173.757034/5629: elapsed=17136.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.757034
last_received_ts = 173.756439
last_seq = 5629
current_ts = 173.774185
current_received_ts = 173.773727
current_seq = 5630
count = 12
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.757034/5629, current 173.774185/5630: elapsed=17141.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.774185
last_received_ts = 173.773727
last_seq = 5630
current_ts = 173.791321
current_received_ts = 173.790787
current_seq = 5631
count = 13
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.774185/5630, current 173.791321/5631: elapsed=17147.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.791321
last_received_ts = 173.790787
last_seq = 5631
current_ts = 173.808472
current_received_ts = 173.808075
current_seq = 5632
count = 14
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.791321/5631, current 173.808472/5632: elapsed=17149.0us expected=17141.5us +- 85.7us, error 0.0%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.808472
last_received_ts = 173.808075
last_seq = 5632
current_ts = 173.825592
current_received_ts = 173.825089
current_seq = 5633
count = 15
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.808472/5632, current 173.825592/5633: elapsed=17115.0us expected=17141.5us +- 85.7us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.825592
last_received_ts = 173.825089
last_seq = 5633
current_ts = 173.842667
current_received_ts = 173.842133
current_seq = 5634
count = 16
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.825592/5633, current 173.842667/5634: elapsed=17076.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.842667
last_received_ts = 173.842133
last_seq = 5634
current_ts = 173.859756
current_received_ts = 173.859222
current_seq = 5635
count = 17
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.842667/5634, current 173.859756/5635: elapsed=17088.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.859756
last_received_ts = 173.859222
last_seq = 5635
current_ts = 173.876831
current_received_ts = 173.876282
current_seq = 5636
count = 18
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.859756/5635, current 173.876831/5636: elapsed=17080.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.876831
last_received_ts = 173.876282
last_seq = 5636
current_ts = 173.893906
current_received_ts = 173.893372
current_seq = 5637
count = 19
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.876831/5636, current 173.893906/5637: elapsed=17075.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.893906
last_received_ts = 173.893372
last_seq = 5637
current_ts = 173.910995
current_received_ts = 173.910461
current_seq = 5638
count = 20
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.893906/5637, current 173.910995/5638: elapsed=17089.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.910995
last_received_ts = 173.910461
last_seq = 5638
current_ts = 173.928085
current_received_ts = 173.927536
current_seq = 5639
count = 21
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.910995/5638, current 173.928085/5639: elapsed=17088.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.928085
last_received_ts = 173.927536
last_seq = 5639
current_ts = 173.945175
current_received_ts = 173.944702
current_seq = 5640
count = 22
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.928085/5639, current 173.945175/5640: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.945175
last_received_ts = 173.944702
last_seq = 5640
current_ts = 173.962250
current_received_ts = 173.961700
current_seq = 5641
count = 23
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.945175/5640, current 173.962250/5641: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.962250
last_received_ts = 173.961700
last_seq = 5641
current_ts = 173.979340
current_received_ts = 173.978806
current_seq = 5642
count = 24
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.962250/5641, current 173.979340/5642: elapsed=17081.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.979340
last_received_ts = 173.978806
last_seq = 5642
current_ts = 173.996414
current_received_ts = 173.995865
current_seq = 5643
count = 25
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.979340/5642, current 173.996414/5643: elapsed=17087.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 173.996414
last_received_ts = 173.995865
last_seq = 5643
current_ts = 174.013504
current_received_ts = 174.013092
current_seq = 5644
count = 26
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 173.996414/5643, current 174.013504/5644: elapsed=17081.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.013504
last_received_ts = 174.013092
last_seq = 5644
current_ts = 174.030594
current_received_ts = 174.030060
current_seq = 5645
count = 27
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.013504/5644, current 174.030594/5645: elapsed=17089.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.030594
last_received_ts = 174.030060
last_seq = 5645
current_ts = 174.047668
current_received_ts = 174.047119
current_seq = 5646
count = 28
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.030594/5645, current 174.047668/5646: elapsed=17079.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.047668
last_received_ts = 174.047119
last_seq = 5646
current_ts = 174.064758
current_received_ts = 174.064224
current_seq = 5647
count = 29
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.047668/5646, current 174.064758/5647: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.064758
last_received_ts = 174.064224
last_seq = 5647
current_ts = 174.081833
current_received_ts = 174.081284
current_seq = 5648
count = 30
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.064758/5647, current 174.081833/5648: elapsed=17088.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.081833
last_received_ts = 174.081284
last_seq = 5648
current_ts = 174.098923
current_received_ts = 174.098373
current_seq = 5649
count = 31
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.081833/5648, current 174.098923/5649: elapsed=17084.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.098923
last_received_ts = 174.098373
last_seq = 5649
current_ts = 174.115997
current_received_ts = 174.115463
current_seq = 5650
count = 32
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.098923/5649, current 174.115997/5650: elapsed=17072.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.115997
last_received_ts = 174.115463
last_seq = 5650
current_ts = 174.133087
current_received_ts = 174.132538
current_seq = 5651
count = 33
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.115997/5650, current 174.133087/5651: elapsed=17089.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.133087
last_received_ts = 174.132538
last_seq = 5651
current_ts = 174.150162
current_received_ts = 174.149612
current_seq = 5652
count = 34
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.133087/5651, current 174.150162/5652: elapsed=17085.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.150162
last_received_ts = 174.149612
last_seq = 5652
current_ts = 174.167252
current_received_ts = 174.166718
current_seq = 5653
count = 35
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.150162/5652, current 174.167252/5653: elapsed=17081.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.167252
last_received_ts = 174.166718
last_seq = 5653
current_ts = 174.184341
current_received_ts = 174.183792
current_seq = 5654
count = 36
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.167252/5653, current 174.184341/5654: elapsed=17089.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.184341
last_received_ts = 174.183792
last_seq = 5654
current_ts = 174.201416
current_received_ts = 174.200867
current_seq = 5655
count = 37
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.184341/5654, current 174.201416/5655: elapsed=17080.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.201416
last_received_ts = 174.200867
last_seq = 5655
current_ts = 174.218491
current_received_ts = 174.217957
current_seq = 5656
count = 38
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.201416/5655, current 174.218491/5656: elapsed=17072.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.218491
last_received_ts = 174.217957
last_seq = 5656
current_ts = 174.235580
current_received_ts = 174.235062
current_seq = 5657
count = 39
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.218491/5656, current 174.235580/5657: elapsed=17097.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.235580
last_received_ts = 174.235062
last_seq = 5657
current_ts = 174.252670
current_received_ts = 174.252106
current_seq = 5658
count = 40
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.235580/5657, current 174.252670/5658: elapsed=17078.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.252670
last_received_ts = 174.252106
last_seq = 5658
current_ts = 174.269745
current_received_ts = 174.269211
current_seq = 5659
count = 41
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.252670/5658, current 174.269745/5659: elapsed=17083.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.269745
last_received_ts = 174.269211
last_seq = 5659
current_ts = 174.286835
current_received_ts = 174.286285
current_seq = 5660
count = 42
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.269745/5659, current 174.286835/5660: elapsed=17083.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.286835
last_received_ts = 174.286285
last_seq = 5660
current_ts = 174.303909
current_received_ts = 174.303375
current_seq = 5661
count = 43
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.286835/5660, current 174.303909/5661: elapsed=17077.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.303909
last_received_ts = 174.303375
last_seq = 5661
current_ts = 174.320999
current_received_ts = 174.320450
current_seq = 5662
count = 44
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.303909/5661, current 174.320999/5662: elapsed=17091.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.320999
last_received_ts = 174.320450
last_seq = 5662
current_ts = 174.338089
current_received_ts = 174.337540
current_seq = 5663
count = 45
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.320999/5662, current 174.338089/5663: elapsed=17087.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.338089
last_received_ts = 174.337540
last_seq = 5663
current_ts = 174.355164
current_received_ts = 174.354614
current_seq = 5664
count = 46
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.338089/5663, current 174.355164/5664: elapsed=17078.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.355164
last_received_ts = 174.354614
last_seq = 5664
current_ts = 174.372253
current_received_ts = 174.371704
current_seq = 5665
count = 47
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.355164/5664, current 174.372253/5665: elapsed=17087.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.372253
last_received_ts = 174.371704
last_seq = 5665
current_ts = 174.389328
current_received_ts = 174.388779
current_seq = 5666
count = 48
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.372253/5665, current 174.389328/5666: elapsed=17079.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.389328
last_received_ts = 174.388779
last_seq = 5666
current_ts = 174.406418
current_received_ts = 174.405853
current_seq = 5667
count = 49
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.389328/5666, current 174.406418/5667: elapsed=17083.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.406418
last_received_ts = 174.405853
last_seq = 5667
current_ts = 174.423492
current_received_ts = 174.422958
current_seq = 5668
count = 50
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.406418/5667, current 174.423492/5668: elapsed=17085.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.423492
last_received_ts = 174.422958
last_seq = 5668
current_ts = 174.440582
current_received_ts = 174.440048
current_seq = 5669
count = 51
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.423492/5668, current 174.440582/5669: elapsed=17085.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.440582
last_received_ts = 174.440048
last_seq = 5669
current_ts = 174.457657
current_received_ts = 174.457108
current_seq = 5670
count = 52
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.440582/5669, current 174.457657/5670: elapsed=17080.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.457657
last_received_ts = 174.457108
last_seq = 5670
current_ts = 174.474747
current_received_ts = 174.474213
current_seq = 5671
count = 53
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.457657/5670, current 174.474747/5671: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.474747
last_received_ts = 174.474213
last_seq = 5671
current_ts = 174.491821
current_received_ts = 174.491287
current_seq = 5672
count = 54
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.474747/5671, current 174.491821/5672: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.491821
last_received_ts = 174.491287
last_seq = 5672
current_ts = 174.508911
current_received_ts = 174.508362
current_seq = 5673
count = 55
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.491821/5672, current 174.508911/5673: elapsed=17087.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.508911
last_received_ts = 174.508362
last_seq = 5673
current_ts = 174.526001
current_received_ts = 174.525452
current_seq = 5674
count = 56
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.508911/5673, current 174.526001/5674: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.526001
last_received_ts = 174.525452
last_seq = 5674
current_ts = 174.543076
current_received_ts = 174.542526
current_seq = 5675
count = 57
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.526001/5674, current 174.543076/5675: elapsed=17084.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.543076
last_received_ts = 174.542526
last_seq = 5675
current_ts = 174.560165
current_received_ts = 174.559616
current_seq = 5676
count = 58
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.543076/5675, current 174.560165/5676: elapsed=17077.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.560165
last_received_ts = 174.559616
last_seq = 5676
current_ts = 174.577240
current_received_ts = 174.576706
current_seq = 5677
count = 59
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.560165/5676, current 174.577240/5677: elapsed=17081.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.577240
last_received_ts = 174.576706
last_seq = 5677
current_ts = 174.594315
current_received_ts = 174.593781
current_seq = 5678
count = 60
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.577240/5677, current 174.594315/5678: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.594315
last_received_ts = 174.593781
last_seq = 5678
current_ts = 174.611404
current_received_ts = 174.610870
current_seq = 5679
count = 61
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.594315/5678, current 174.611404/5679: elapsed=17087.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.611404
last_received_ts = 174.610870
last_seq = 5679
current_ts = 174.628494
current_received_ts = 174.627945
current_seq = 5680
count = 62
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.611404/5679, current 174.628494/5680: elapsed=17079.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.628494
last_received_ts = 174.627945
last_seq = 5680
current_ts = 174.645584
current_received_ts = 174.645050
current_seq = 5681
count = 63
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.628494/5680, current 174.645584/5681: elapsed=17092.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.645584
last_received_ts = 174.645050
last_seq = 5681
current_ts = 174.662659
current_received_ts = 174.662109
current_seq = 5682
count = 64
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.645584/5681, current 174.662659/5682: elapsed=17074.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.662659
last_received_ts = 174.662109
last_seq = 5682
current_ts = 174.679749
current_received_ts = 174.679214
current_seq = 5683
count = 65
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.662659/5682, current 174.679749/5683: elapsed=17094.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.679749
last_received_ts = 174.679214
last_seq = 5683
current_ts = 174.696823
current_received_ts = 174.696289
current_seq = 5684
count = 66
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.679749/5683, current 174.696823/5684: elapsed=17083.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.696823
last_received_ts = 174.696289
last_seq = 5684
current_ts = 174.713898
current_received_ts = 174.713364
current_seq = 5685
count = 67
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.696823/5684, current 174.713898/5685: elapsed=17075.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.713898
last_received_ts = 174.713364
last_seq = 5685
current_ts = 174.730988
current_received_ts = 174.730438
current_seq = 5686
count = 68
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.713898/5685, current 174.730988/5686: elapsed=17090.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.730988
last_received_ts = 174.730438
last_seq = 5686
current_ts = 174.748077
current_received_ts = 174.747528
current_seq = 5687
count = 69
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.730988/5686, current 174.748077/5687: elapsed=17083.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.748077
last_received_ts = 174.747528
last_seq = 5687
current_ts = 174.765152
current_received_ts = 174.764694
current_seq = 5688
count = 70
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.748077/5687, current 174.765152/5688: elapsed=17077.0us expected=17141.5us +- 85.7us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.765152
last_received_ts = 174.764694
last_seq = 5688
current_ts = 174.782242
current_received_ts = 174.781845
current_seq = 5689
count = 71
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.765152/5688, current 174.782242/5689: elapsed=17082.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.782242
last_received_ts = 174.781845
last_seq = 5689
current_ts = 174.799332
current_received_ts = 174.798798
current_seq = 5690
count = 72
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.782242/5689, current 174.799332/5690: elapsed=17094.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.799332
last_received_ts = 174.798798
last_seq = 5690
current_ts = 174.816422
current_received_ts = 174.815826
current_seq = 5691
count = 73
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.799332/5690, current 174.816422/5691: elapsed=17085.0us expected=17141.5us +- 85.7us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 174.816422
last_received_ts = 174.815826
last_seq = 5691
current_ts = 174.833435
current_received_ts = 174.832962
current_seq = 5692
count = 74
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 174.816422/5691, current 174.833435/5692: elapsed=17019.0us expected=17141.5us +- 85.7us, error 0.7%
(kms_flip:3861) DEBUG: inconsistent flip ts/seq: last 174.816422/5691, current 174.833435/5692: elapsed=17019.0us expected=17141.5us
(kms_flip:3861) DEBUG: expected 65406, counted 74, encoder type 2
(kms_flip:3861) DEBUG: dropped frames, expected 65406, counted 74, encoder type 2
(kms_flip:3861) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3861) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3861) igt_core-INFO: Stack trace:
(kms_flip:3861) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3861) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3861) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3861) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3861) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3861) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3861) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3861) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (4.818s)
Starting dynamic subtest: B-HDMI-A2
(kms_flip:3861) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3861) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3861) DEBUG: flip ts/seq: last 178.801849/4079, current 178.818741/4080: elapsed=16903.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.818741
last_received_ts = 178.818207
last_seq = 4080
current_ts = 178.835632
current_received_ts = 178.835098
current_seq = 4081
count = 25
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.818741/4080, current 178.835632/4081: elapsed=16886.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.835632
last_received_ts = 178.835098
last_seq = 4081
current_ts = 178.852524
current_received_ts = 178.851974
current_seq = 4082
count = 26
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.835632/4081, current 178.852524/4082: elapsed=16891.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.852524
last_received_ts = 178.851974
last_seq = 4082
current_ts = 178.869400
current_received_ts = 178.868851
current_seq = 4083
count = 27
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.852524/4082, current 178.869400/4083: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.869400
last_received_ts = 178.868851
last_seq = 4083
current_ts = 178.886292
current_received_ts = 178.885742
current_seq = 4084
count = 28
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.869400/4083, current 178.886292/4084: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.886292
last_received_ts = 178.885742
last_seq = 4084
current_ts = 178.903168
current_received_ts = 178.902634
current_seq = 4085
count = 29
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.886292/4084, current 178.903168/4085: elapsed=16878.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.903168
last_received_ts = 178.902634
last_seq = 4085
current_ts = 178.920059
current_received_ts = 178.919510
current_seq = 4086
count = 30
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.903168/4085, current 178.920059/4086: elapsed=16894.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.920059
last_received_ts = 178.919510
last_seq = 4086
current_ts = 178.936951
current_received_ts = 178.936386
current_seq = 4087
count = 31
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.920059/4086, current 178.936951/4087: elapsed=16883.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.936951
last_received_ts = 178.936386
last_seq = 4087
current_ts = 178.953827
current_received_ts = 178.953278
current_seq = 4088
count = 32
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.936951/4087, current 178.953827/4088: elapsed=16879.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.953827
last_received_ts = 178.953278
last_seq = 4088
current_ts = 178.970718
current_received_ts = 178.970154
current_seq = 4089
count = 33
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.953827/4088, current 178.970718/4089: elapsed=16890.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.970718
last_received_ts = 178.970154
last_seq = 4089
current_ts = 178.987595
current_received_ts = 178.987061
current_seq = 4090
count = 34
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.970718/4089, current 178.987595/4090: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 178.987595
last_received_ts = 178.987061
last_seq = 4090
current_ts = 179.004486
current_received_ts = 179.003937
current_seq = 4091
count = 35
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 178.987595/4090, current 179.004486/4091: elapsed=16880.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.004486
last_received_ts = 179.003937
last_seq = 4091
current_ts = 179.021378
current_received_ts = 179.020813
current_seq = 4092
count = 36
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.004486/4091, current 179.021378/4092: elapsed=16890.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.021378
last_received_ts = 179.020813
last_seq = 4092
current_ts = 179.038254
current_received_ts = 179.037704
current_seq = 4093
count = 37
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.021378/4092, current 179.038254/4093: elapsed=16886.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.038254
last_received_ts = 179.037704
last_seq = 4093
current_ts = 179.055145
current_received_ts = 179.054581
current_seq = 4094
count = 38
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.038254/4093, current 179.055145/4094: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.055145
last_received_ts = 179.054581
last_seq = 4094
current_ts = 179.072021
current_received_ts = 179.071472
current_seq = 4095
count = 39
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.055145/4094, current 179.072021/4095: elapsed=16887.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.072021
last_received_ts = 179.071472
last_seq = 4095
current_ts = 179.088913
current_received_ts = 179.088348
current_seq = 4096
count = 40
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.072021/4095, current 179.088913/4096: elapsed=16882.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.088913
last_received_ts = 179.088348
last_seq = 4096
current_ts = 179.105804
current_received_ts = 179.105240
current_seq = 4097
count = 41
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.088913/4096, current 179.105804/4097: elapsed=16888.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.105804
last_received_ts = 179.105240
last_seq = 4097
current_ts = 179.122681
current_received_ts = 179.122131
current_seq = 4098
count = 42
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.105804/4097, current 179.122681/4098: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.122681
last_received_ts = 179.122131
last_seq = 4098
current_ts = 179.139557
current_received_ts = 179.139038
current_seq = 4099
count = 43
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.122681/4098, current 179.139557/4099: elapsed=16877.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.139557
last_received_ts = 179.139038
last_seq = 4099
current_ts = 179.156448
current_received_ts = 179.155899
current_seq = 4100
count = 44
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.139557/4099, current 179.156448/4100: elapsed=16892.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.156448
last_received_ts = 179.155899
last_seq = 4100
current_ts = 179.173340
current_received_ts = 179.172775
current_seq = 4101
count = 45
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.156448/4100, current 179.173340/4101: elapsed=16887.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.173340
last_received_ts = 179.172775
last_seq = 4101
current_ts = 179.190216
current_received_ts = 179.189667
current_seq = 4102
count = 46
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.173340/4101, current 179.190216/4102: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.190216
last_received_ts = 179.189667
last_seq = 4102
current_ts = 179.207108
current_received_ts = 179.206558
current_seq = 4103
count = 47
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.190216/4102, current 179.207108/4103: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.207108
last_received_ts = 179.206558
last_seq = 4103
current_ts = 179.223984
current_received_ts = 179.223434
current_seq = 4104
count = 48
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.207108/4103, current 179.223984/4104: elapsed=16883.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.223984
last_received_ts = 179.223434
last_seq = 4104
current_ts = 179.240875
current_received_ts = 179.240326
current_seq = 4105
count = 49
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.223984/4104, current 179.240875/4105: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.240875
last_received_ts = 179.240326
last_seq = 4105
current_ts = 179.257751
current_received_ts = 179.257202
current_seq = 4106
count = 50
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.240875/4105, current 179.257751/4106: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.257751
last_received_ts = 179.257202
last_seq = 4106
current_ts = 179.274643
current_received_ts = 179.274094
current_seq = 4107
count = 51
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.257751/4106, current 179.274643/4107: elapsed=16887.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.274643
last_received_ts = 179.274094
last_seq = 4107
current_ts = 179.291534
current_received_ts = 179.290970
current_seq = 4108
count = 52
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.274643/4107, current 179.291534/4108: elapsed=16883.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.291534
last_received_ts = 179.290970
last_seq = 4108
current_ts = 179.308411
current_received_ts = 179.307861
current_seq = 4109
count = 53
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.291534/4108, current 179.308411/4109: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.308411
last_received_ts = 179.307861
last_seq = 4109
current_ts = 179.325302
current_received_ts = 179.324738
current_seq = 4110
count = 54
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.308411/4109, current 179.325302/4110: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.325302
last_received_ts = 179.324738
last_seq = 4110
current_ts = 179.342178
current_received_ts = 179.341629
current_seq = 4111
count = 55
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.325302/4110, current 179.342178/4111: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.342178
last_received_ts = 179.341629
last_seq = 4111
current_ts = 179.359070
current_received_ts = 179.358521
current_seq = 4112
count = 56
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.342178/4111, current 179.359070/4112: elapsed=16887.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.359070
last_received_ts = 179.358521
last_seq = 4112
current_ts = 179.375961
current_received_ts = 179.375397
current_seq = 4113
count = 57
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.359070/4112, current 179.375961/4113: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.375961
last_received_ts = 179.375397
last_seq = 4113
current_ts = 179.392838
current_received_ts = 179.392288
current_seq = 4114
count = 58
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.375961/4113, current 179.392838/4114: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.392838
last_received_ts = 179.392288
last_seq = 4114
current_ts = 179.409729
current_received_ts = 179.409164
current_seq = 4115
count = 59
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.392838/4114, current 179.409729/4115: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.409729
last_received_ts = 179.409164
last_seq = 4115
current_ts = 179.426605
current_received_ts = 179.426071
current_seq = 4116
count = 60
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.409729/4115, current 179.426605/4116: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.426605
last_received_ts = 179.426071
last_seq = 4116
current_ts = 179.443497
current_received_ts = 179.442947
current_seq = 4117
count = 61
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.426605/4116, current 179.443497/4117: elapsed=16890.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.443497
last_received_ts = 179.442947
last_seq = 4117
current_ts = 179.460373
current_received_ts = 179.459824
current_seq = 4118
count = 62
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.443497/4117, current 179.460373/4118: elapsed=16881.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.460373
last_received_ts = 179.459824
last_seq = 4118
current_ts = 179.477264
current_received_ts = 179.476715
current_seq = 4119
count = 63
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.460373/4118, current 179.477264/4119: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.477264
last_received_ts = 179.476715
last_seq = 4119
current_ts = 179.494156
current_received_ts = 179.493591
current_seq = 4120
count = 64
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.477264/4119, current 179.494156/4120: elapsed=16887.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.494156
last_received_ts = 179.493591
last_seq = 4120
current_ts = 179.511032
current_received_ts = 179.510483
current_seq = 4121
count = 65
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.494156/4120, current 179.511032/4121: elapsed=16882.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.511032
last_received_ts = 179.510483
last_seq = 4121
current_ts = 179.527924
current_received_ts = 179.527374
current_seq = 4122
count = 66
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.511032/4121, current 179.527924/4122: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.527924
last_received_ts = 179.527374
last_seq = 4122
current_ts = 179.544800
current_received_ts = 179.544250
current_seq = 4123
count = 67
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.527924/4122, current 179.544800/4123: elapsed=16877.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.544800
last_received_ts = 179.544250
last_seq = 4123
current_ts = 179.561691
current_received_ts = 179.561127
current_seq = 4124
count = 68
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.544800/4123, current 179.561691/4124: elapsed=16894.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.561691
last_received_ts = 179.561127
last_seq = 4124
current_ts = 179.578568
current_received_ts = 179.578049
current_seq = 4125
count = 69
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.561691/4124, current 179.578568/4125: elapsed=16879.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.578568
last_received_ts = 179.578049
last_seq = 4125
current_ts = 179.595444
current_received_ts = 179.594925
current_seq = 4126
count = 70
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.578568/4125, current 179.595444/4126: elapsed=16882.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.595444
last_received_ts = 179.594925
last_seq = 4126
current_ts = 179.612335
current_received_ts = 179.611786
current_seq = 4127
count = 71
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.595444/4126, current 179.612335/4127: elapsed=16893.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.612335
last_received_ts = 179.611786
last_seq = 4127
current_ts = 179.629227
current_received_ts = 179.628677
current_seq = 4128
count = 72
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.612335/4127, current 179.629227/4128: elapsed=16888.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.629227
last_received_ts = 179.628677
last_seq = 4128
current_ts = 179.646103
current_received_ts = 179.645554
current_seq = 4129
count = 73
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.629227/4128, current 179.646103/4129: elapsed=16881.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.646103
last_received_ts = 179.645554
last_seq = 4129
current_ts = 179.662994
current_received_ts = 179.662445
current_seq = 4130
count = 74
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.646103/4129, current 179.662994/4130: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.662994
last_received_ts = 179.662445
last_seq = 4130
current_ts = 179.679886
current_received_ts = 179.679337
current_seq = 4131
count = 75
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.662994/4130, current 179.679886/4131: elapsed=16890.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.679886
last_received_ts = 179.679337
last_seq = 4131
current_ts = 179.696762
current_received_ts = 179.696213
current_seq = 4132
count = 76
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.679886/4131, current 179.696762/4132: elapsed=16871.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.696762
last_received_ts = 179.696213
last_seq = 4132
current_ts = 179.713654
current_received_ts = 179.713089
current_seq = 4133
count = 77
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.696762/4132, current 179.713654/4133: elapsed=16895.0us expected=16914.8us +- 84.6us, error 0.1%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.713654
last_received_ts = 179.713089
last_seq = 4133
current_ts = 179.730530
current_received_ts = 179.729980
current_seq = 4134
count = 78
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.713654/4133, current 179.730530/4134: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.730530
last_received_ts = 179.729980
last_seq = 4134
current_ts = 179.747421
current_received_ts = 179.746872
current_seq = 4135
count = 79
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.730530/4134, current 179.747421/4135: elapsed=16885.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.747421
last_received_ts = 179.746872
last_seq = 4135
current_ts = 179.764313
current_received_ts = 179.763748
current_seq = 4136
count = 80
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.747421/4135, current 179.764313/4136: elapsed=16889.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.764313
last_received_ts = 179.763748
last_seq = 4136
current_ts = 179.781189
current_received_ts = 179.780640
current_seq = 4137
count = 81
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.764313/4136, current 179.781189/4137: elapsed=16880.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.781189
last_received_ts = 179.780640
last_seq = 4137
current_ts = 179.798080
current_received_ts = 179.797516
current_seq = 4138
count = 82
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.781189/4137, current 179.798080/4138: elapsed=16886.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.798080
last_received_ts = 179.797516
last_seq = 4138
current_ts = 179.814957
current_received_ts = 179.814407
current_seq = 4139
count = 83
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.798080/4138, current 179.814957/4139: elapsed=16884.0us expected=16914.8us +- 84.6us, error 0.2%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.814957
last_received_ts = 179.814407
last_seq = 4139
current_ts = 179.831818
current_received_ts = 179.831268
current_seq = 4140
count = 84
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.814957/4139, current 179.831818/4140: elapsed=16863.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.831818
last_received_ts = 179.831268
last_seq = 4140
current_ts = 179.848679
current_received_ts = 179.848129
current_seq = 4141
count = 85
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.831818/4140, current 179.848679/4141: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.848679
last_received_ts = 179.848129
last_seq = 4141
current_ts = 179.865540
current_received_ts = 179.864990
current_seq = 4142
count = 86
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.848679/4141, current 179.865540/4142: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.865540
last_received_ts = 179.864990
last_seq = 4142
current_ts = 179.882401
current_received_ts = 179.881851
current_seq = 4143
count = 87
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.865540/4142, current 179.882401/4143: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.882401
last_received_ts = 179.881851
last_seq = 4143
current_ts = 179.899261
current_received_ts = 179.898697
current_seq = 4144
count = 88
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.882401/4143, current 179.899261/4144: elapsed=16856.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.899261
last_received_ts = 179.898697
last_seq = 4144
current_ts = 179.916122
current_received_ts = 179.915558
current_seq = 4145
count = 89
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.899261/4144, current 179.916122/4145: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.916122
last_received_ts = 179.915558
last_seq = 4145
current_ts = 179.932968
current_received_ts = 179.932419
current_seq = 4146
count = 90
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.916122/4145, current 179.932968/4146: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.932968
last_received_ts = 179.932419
last_seq = 4146
current_ts = 179.949829
current_received_ts = 179.949280
current_seq = 4147
count = 91
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.932968/4146, current 179.949829/4147: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.949829
last_received_ts = 179.949280
last_seq = 4147
current_ts = 179.966690
current_received_ts = 179.966141
current_seq = 4148
count = 92
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.949829/4147, current 179.966690/4148: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.966690
last_received_ts = 179.966141
last_seq = 4148
current_ts = 179.983551
current_received_ts = 179.983002
current_seq = 4149
count = 93
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.966690/4148, current 179.983551/4149: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 179.983551
last_received_ts = 179.983002
last_seq = 4149
current_ts = 180.000412
current_received_ts = 179.999847
current_seq = 4150
count = 94
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 179.983551/4149, current 180.000412/4150: elapsed=16854.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.000412
last_received_ts = 179.999847
last_seq = 4150
current_ts = 180.017273
current_received_ts = 180.016708
current_seq = 4151
count = 95
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.000412/4150, current 180.017273/4151: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.017273
last_received_ts = 180.016708
last_seq = 4151
current_ts = 180.034119
current_received_ts = 180.033569
current_seq = 4152
count = 96
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.017273/4151, current 180.034119/4152: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.034119
last_received_ts = 180.033569
last_seq = 4152
current_ts = 180.050980
current_received_ts = 180.050430
current_seq = 4153
count = 97
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.034119/4152, current 180.050980/4153: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.050980
last_received_ts = 180.050430
last_seq = 4153
current_ts = 180.067841
current_received_ts = 180.067291
current_seq = 4154
count = 98
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.050980/4153, current 180.067841/4154: elapsed=16850.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.067841
last_received_ts = 180.067291
last_seq = 4154
current_ts = 180.084702
current_received_ts = 180.084152
current_seq = 4155
count = 99
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.067841/4154, current 180.084702/4155: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.084702
last_received_ts = 180.084152
last_seq = 4155
current_ts = 180.101562
current_received_ts = 180.101044
current_seq = 4156
count = 100
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.084702/4155, current 180.101562/4156: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.101562
last_received_ts = 180.101044
last_seq = 4156
current_ts = 180.118408
current_received_ts = 180.117874
current_seq = 4157
count = 101
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.101562/4156, current 180.118408/4157: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.118408
last_received_ts = 180.117874
last_seq = 4157
current_ts = 180.135284
current_received_ts = 180.134720
current_seq = 4158
count = 102
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.118408/4157, current 180.135284/4158: elapsed=16863.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.135284
last_received_ts = 180.134720
last_seq = 4158
current_ts = 180.152145
current_received_ts = 180.151581
current_seq = 4159
count = 103
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.135284/4158, current 180.152145/4159: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.152145
last_received_ts = 180.151581
last_seq = 4159
current_ts = 180.168991
current_received_ts = 180.168442
current_seq = 4160
count = 104
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.152145/4159, current 180.168991/4160: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.168991
last_received_ts = 180.168442
last_seq = 4160
current_ts = 180.185852
current_received_ts = 180.185303
current_seq = 4161
count = 105
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.168991/4160, current 180.185852/4161: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.185852
last_received_ts = 180.185303
last_seq = 4161
current_ts = 180.202713
current_received_ts = 180.202164
current_seq = 4162
count = 106
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.185852/4161, current 180.202713/4162: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.202713
last_received_ts = 180.202164
last_seq = 4162
current_ts = 180.219574
current_received_ts = 180.219040
current_seq = 4163
count = 107
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.202713/4162, current 180.219574/4163: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.219574
last_received_ts = 180.219040
last_seq = 4163
current_ts = 180.236435
current_received_ts = 180.235886
current_seq = 4164
count = 108
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.219574/4163, current 180.236435/4164: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.236435
last_received_ts = 180.235886
last_seq = 4164
current_ts = 180.253296
current_received_ts = 180.252731
current_seq = 4165
count = 109
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.236435/4164, current 180.253296/4165: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.253296
last_received_ts = 180.252731
last_seq = 4165
current_ts = 180.270142
current_received_ts = 180.269592
current_seq = 4166
count = 110
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.253296/4165, current 180.270142/4166: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.270142
last_received_ts = 180.269592
last_seq = 4166
current_ts = 180.287003
current_received_ts = 180.286453
current_seq = 4167
count = 111
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.270142/4166, current 180.287003/4167: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.287003
last_received_ts = 180.286453
last_seq = 4167
current_ts = 180.303864
current_received_ts = 180.303314
current_seq = 4168
count = 112
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.287003/4167, current 180.303864/4168: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.303864
last_received_ts = 180.303314
last_seq = 4168
current_ts = 180.320724
current_received_ts = 180.320175
current_seq = 4169
count = 113
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.303864/4168, current 180.320724/4169: elapsed=16862.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.320724
last_received_ts = 180.320175
last_seq = 4169
current_ts = 180.337585
current_received_ts = 180.337036
current_seq = 4170
count = 114
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.320724/4169, current 180.337585/4170: elapsed=16855.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.337585
last_received_ts = 180.337036
last_seq = 4170
current_ts = 180.354446
current_received_ts = 180.353882
current_seq = 4171
count = 115
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.337585/4170, current 180.354446/4171: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.354446
last_received_ts = 180.353882
last_seq = 4171
current_ts = 180.371307
current_received_ts = 180.370743
current_seq = 4172
count = 116
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.354446/4171, current 180.371307/4172: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.371307
last_received_ts = 180.370743
last_seq = 4172
current_ts = 180.388153
current_received_ts = 180.387604
current_seq = 4173
count = 117
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.371307/4172, current 180.388153/4173: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.388153
last_received_ts = 180.387604
last_seq = 4173
current_ts = 180.405014
current_received_ts = 180.404465
current_seq = 4174
count = 118
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.388153/4173, current 180.405014/4174: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.405014
last_received_ts = 180.404465
last_seq = 4174
current_ts = 180.421875
current_received_ts = 180.421326
current_seq = 4175
count = 119
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.405014/4174, current 180.421875/4175: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.421875
last_received_ts = 180.421326
last_seq = 4175
current_ts = 180.438736
current_received_ts = 180.438187
current_seq = 4176
count = 120
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.421875/4175, current 180.438736/4176: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.438736
last_received_ts = 180.438187
last_seq = 4176
current_ts = 180.455597
current_received_ts = 180.455048
current_seq = 4177
count = 121
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.438736/4176, current 180.455597/4177: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.455597
last_received_ts = 180.455048
last_seq = 4177
current_ts = 180.472458
current_received_ts = 180.471909
current_seq = 4178
count = 122
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.455597/4177, current 180.472458/4178: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.472458
last_received_ts = 180.471909
last_seq = 4178
current_ts = 180.489319
current_received_ts = 180.488754
current_seq = 4179
count = 123
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.472458/4178, current 180.489319/4179: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.489319
last_received_ts = 180.488754
last_seq = 4179
current_ts = 180.506165
current_received_ts = 180.505615
current_seq = 4180
count = 124
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.489319/4179, current 180.506165/4180: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.506165
last_received_ts = 180.505615
last_seq = 4180
current_ts = 180.523026
current_received_ts = 180.522476
current_seq = 4181
count = 125
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.506165/4180, current 180.523026/4181: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.523026
last_received_ts = 180.522476
last_seq = 4181
current_ts = 180.539886
current_received_ts = 180.539337
current_seq = 4182
count = 126
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.523026/4181, current 180.539886/4182: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.539886
last_received_ts = 180.539337
last_seq = 4182
current_ts = 180.556747
current_received_ts = 180.556198
current_seq = 4183
count = 127
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.539886/4182, current 180.556747/4183: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.556747
last_received_ts = 180.556198
last_seq = 4183
current_ts = 180.573608
current_received_ts = 180.573059
current_seq = 4184
count = 128
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.556747/4183, current 180.573608/4184: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.573608
last_received_ts = 180.573059
last_seq = 4184
current_ts = 180.590469
current_received_ts = 180.589920
current_seq = 4185
count = 129
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.573608/4184, current 180.590469/4185: elapsed=16862.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.590469
last_received_ts = 180.589920
last_seq = 4185
current_ts = 180.607330
current_received_ts = 180.606766
current_seq = 4186
count = 130
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.590469/4185, current 180.607330/4186: elapsed=16856.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.607330
last_received_ts = 180.606766
last_seq = 4186
current_ts = 180.624176
current_received_ts = 180.623627
current_seq = 4187
count = 131
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.607330/4186, current 180.624176/4187: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.624176
last_received_ts = 180.623627
last_seq = 4187
current_ts = 180.641052
current_received_ts = 180.640488
current_seq = 4188
count = 132
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.624176/4187, current 180.641052/4188: elapsed=16862.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.641052
last_received_ts = 180.640488
last_seq = 4188
current_ts = 180.657898
current_received_ts = 180.657349
current_seq = 4189
count = 133
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.641052/4188, current 180.657898/4189: elapsed=16855.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.657898
last_received_ts = 180.657349
last_seq = 4189
current_ts = 180.674759
current_received_ts = 180.674210
current_seq = 4190
count = 134
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.657898/4189, current 180.674759/4190: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.674759
last_received_ts = 180.674210
last_seq = 4190
current_ts = 180.691620
current_received_ts = 180.691071
current_seq = 4191
count = 135
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.674759/4190, current 180.691620/4191: elapsed=16858.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.691620
last_received_ts = 180.691071
last_seq = 4191
current_ts = 180.708481
current_received_ts = 180.707932
current_seq = 4192
count = 136
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.691620/4191, current 180.708481/4192: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.708481
last_received_ts = 180.707932
last_seq = 4192
current_ts = 180.725342
current_received_ts = 180.724777
current_seq = 4193
count = 137
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.708481/4192, current 180.725342/4193: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.725342
last_received_ts = 180.724777
last_seq = 4193
current_ts = 180.742203
current_received_ts = 180.741638
current_seq = 4194
count = 138
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.725342/4193, current 180.742203/4194: elapsed=16860.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.742203
last_received_ts = 180.741638
last_seq = 4194
current_ts = 180.759048
current_received_ts = 180.758499
current_seq = 4195
count = 139
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.742203/4194, current 180.759048/4195: elapsed=16857.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.759048
last_received_ts = 180.758499
last_seq = 4195
current_ts = 180.775909
current_received_ts = 180.775360
current_seq = 4196
count = 140
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.759048/4195, current 180.775909/4196: elapsed=16859.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.775909
last_received_ts = 180.775360
last_seq = 4196
current_ts = 180.792755
current_received_ts = 180.792221
current_seq = 4197
count = 141
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.775909/4196, current 180.792755/4197: elapsed=16850.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.792755
last_received_ts = 180.792221
last_seq = 4197
current_ts = 180.809616
current_received_ts = 180.809082
current_seq = 4198
count = 142
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.792755/4197, current 180.809616/4198: elapsed=16861.0us expected=16914.8us +- 84.6us, error 0.3%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.809616
last_received_ts = 180.809082
last_seq = 4198
current_ts = 180.826477
current_received_ts = 180.825928
current_seq = 4199
count = 143
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.809616/4198, current 180.826477/4199: elapsed=16853.0us expected=16914.8us +- 84.6us, error 0.4%
(kms_flip:3861) DEBUG: name = flip
last_ts = 180.826477
last_received_ts = 180.825928
last_seq = 4199
current_ts = 180.843307
current_received_ts = 180.842758
current_seq = 4200
count = 144
seq_step = 1
(kms_flip:3861) DEBUG: flip ts/seq: last 180.826477/4199, current 180.843307/4200: elapsed=16827.0us expected=16914.8us +- 84.6us, error 0.5%
(kms_flip:3861) DEBUG: inconsistent flip ts/seq: last 180.826477/4199, current 180.843307/4200: elapsed=16827.0us expected=16914.8us
(kms_flip:3861) DEBUG: expected 66283, counted 144, encoder type 2
(kms_flip:3861) DEBUG: dropped frames, expected 66283, counted 144, encoder type 2
(kms_flip:3861) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3861) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3861) igt_core-INFO: Stack trace:
(kms_flip:3861) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3861) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3861) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3861) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3861) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3861) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3861) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3861) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (6.266s)
Starting dynamic subtest: C-HDMI-A2
Dynamic subtest C-HDMI-A2: SUCCESS (4.222s)
Starting dynamic subtest: D-HDMI-A2
Dynamic subtest D-HDMI-A2: SUCCESS (4.248s)
Starting dynamic subtest: A-DP2
Dynamic subtest A-DP2: SUCCESS (4.295s)
Starting dynamic subtest: B-DP2
Dynamic subtest B-DP2: SUCCESS (4.272s)
Starting dynamic subtest: C-DP2
Dynamic subtest C-DP2: SUCCESS (4.265s)
Starting dynamic subtest: D-DP2
Dynamic subtest D-DP2: SUCCESS (4.258s)
Subtest plain-flip-ts-check: FAIL (36.668s)