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

shard-bmg-8

IGT-Version: 1.30-g2c9202bdb (x86_64) (Linux: 6.14.0-rc2-xe+ x86_64)

Using IGT_SRANDOM=1739345677 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16145.4us +- 29.523us accuracy 0.55%
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AB-DP2-HDMI-A3: FAIL (0.686s)
Starting dynamic subtest: AC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16195.3us +- 2.955us accuracy 0.05%
vblank interval differs from modeline! expected 16666.7us, measured 16195us +- 2.955us, difference 471.4us (159.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AC-DP2-HDMI-A3: FAIL (5.045s)
Starting dynamic subtest: AD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16421.2us +- 2.040us accuracy 0.04%
vblank interval differs from modeline! expected 16666.7us, measured 16421us +- 2.040us, difference 245.5us (120.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AD-DP2-HDMI-A3: FAIL (7.478s)
Starting dynamic subtest: BC-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16569.3us +- 7.905us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16569us +- 7.905us, difference 97.4us (12.3 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.710s)
Starting dynamic subtest: BD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16617.9us +- 4.951us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16618us +- 4.951us, difference 48.8us (9.9 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.680s)
Starting dynamic subtest: CD-DP2-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Expected frametime: 16667us; measured 16640.7us +- 3.873us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 16641us +- 3.873us, difference 25.9us (6.7 sigma)
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.664s)
Subtest 2x-plain-flip-ts-check: FAIL (30.312s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:7572) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:7572) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:7572) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:7572) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee71210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee71210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee7faa0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee7faa0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eeb70a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eeb70a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eeb70a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eeb70a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7572) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:7572) DEBUG: No stale events found
(kms_flip:7572) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7572) INFO: Expected frametime: 16667us; measured 16145.4us +- 29.523us accuracy 0.55%
(kms_flip:7572) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:7572) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
(kms_flip:7572) igt_core-INFO: Stack trace:
(kms_flip:7572) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7572) igt_core-INFO:   #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
(kms_flip:7572) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7572) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7572) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7572) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7572) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7572) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (0.686s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:7572) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7572) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:7572) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7572) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:7572) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eef7390, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02eef7390, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee830e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee830e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee82f80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee82f80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee830e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) intel_allocator_simple-DEBUG: <ial: 0x5ef02ee830e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7572) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7572) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:7572) DEBUG: No stale events found
(kms_flip:7572) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7572) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7572) INFO: Expected frametime: 16667us; measured 16195.3us +- 2.955us accuracy 0.05%
(kms_flip:7572) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16195us +- 2.955us, difference 471.4us (159.5 sigma)
(kms_flip:7572) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 273.943970
current_received_ts = 273.943390
current_seq = 11777
count = 0
seq_step = 1
(kms_flip:7572) DEBUG: name = flip
last_ts = 273.943970
last_received_ts = 273.943390
last_seq = 11777
current_ts = 273.960175
current_received_ts = 273.959564
current_seq = 11778
count = 1
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 273.943970/11777, current 273.960175/11778: elapsed=16194.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 273.960175
last_received_ts = 273.959564
last_seq = 11778
current_ts = 273.976379
current_received_ts = 273.975769
current_seq = 11779
count = 2
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 273.960175/11778, current 273.976379/11779: elapsed=16194.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 273.976379
last_received_ts = 273.975769
last_seq = 11779
current_ts = 273.992554
current_received_ts = 273.991974
current_seq = 11780
count = 3
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 273.976379/11779, current 273.992554/11780: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 273.992554
last_received_ts = 273.991974
last_seq = 11780
current_ts = 274.008759
current_received_ts = 274.008148
current_seq = 11781
count = 4
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 273.992554/11780, current 274.008759/11781: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.008759
last_received_ts = 274.008148
last_seq = 11781
current_ts = 274.024963
current_received_ts = 274.024353
current_seq = 11782
count = 5
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.008759/11781, current 274.024963/11782: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.024963
last_received_ts = 274.024353
last_seq = 11782
current_ts = 274.041168
current_received_ts = 274.040558
current_seq = 11783
count = 6
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.024963/11782, current 274.041168/11783: elapsed=16194.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.041168
last_received_ts = 274.040558
last_seq = 11783
current_ts = 274.057343
current_received_ts = 274.056732
current_seq = 11784
count = 7
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.041168/11783, current 274.057343/11784: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.057343
last_received_ts = 274.056732
last_seq = 11784
current_ts = 274.073547
current_received_ts = 274.072937
current_seq = 11785
count = 8
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.057343/11784, current 274.073547/11785: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.073547
last_received_ts = 274.072937
last_seq = 11785
current_ts = 274.089752
current_received_ts = 274.089142
current_seq = 11786
count = 9
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.073547/11785, current 274.089752/11786: elapsed=16194.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.089752
last_received_ts = 274.089142
last_seq = 11786
current_ts = 274.105927
current_received_ts = 274.105316
current_seq = 11787
count = 10
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.089752/11786, current 274.105927/11787: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.105927
last_received_ts = 274.105316
last_seq = 11787
current_ts = 274.122131
current_received_ts = 274.121521
current_seq = 11788
count = 11
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.105927/11787, current 274.122131/11788: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.122131
last_received_ts = 274.121521
last_seq = 11788
current_ts = 274.138336
current_received_ts = 274.137726
current_seq = 11789
count = 12
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.122131/11788, current 274.138336/11789: elapsed=16195.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.138336
last_received_ts = 274.137726
last_seq = 11789
current_ts = 274.154510
current_received_ts = 274.153900
current_seq = 11790
count = 13
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.138336/11789, current 274.154510/11790: elapsed=16195.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.154510
last_received_ts = 274.153900
last_seq = 11790
current_ts = 274.170715
current_received_ts = 274.170105
current_seq = 11791
count = 14
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.154510/11790, current 274.170715/11791: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.170715
last_received_ts = 274.170105
last_seq = 11791
current_ts = 274.186920
current_received_ts = 274.186310
current_seq = 11792
count = 15
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.170715/11791, current 274.186920/11792: elapsed=16195.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.186920
last_received_ts = 274.186310
last_seq = 11792
current_ts = 274.203094
current_received_ts = 274.202515
current_seq = 11793
count = 16
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.186920/11792, current 274.203094/11793: elapsed=16195.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.203094
last_received_ts = 274.202515
last_seq = 11793
current_ts = 274.219299
current_received_ts = 274.218689
current_seq = 11794
count = 17
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.203094/11793, current 274.219299/11794: elapsed=16196.0us expected=16195.3us +- 81.0us, error 0.0%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.219299
last_received_ts = 274.218689
last_seq = 11794
current_ts = 274.235535
current_received_ts = 274.234955
current_seq = 11795
count = 18
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.219299/11794, current 274.235535/11795: elapsed=16245.0us expected=16195.3us +- 81.0us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.235535
last_received_ts = 274.234955
last_seq = 11795
current_ts = 274.251801
current_received_ts = 274.251190
current_seq = 11796
count = 19
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.235535/11795, current 274.251801/11796: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.251801
last_received_ts = 274.251190
last_seq = 11796
current_ts = 274.268066
current_received_ts = 274.267456
current_seq = 11797
count = 20
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.251801/11796, current 274.268066/11797: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.268066
last_received_ts = 274.267456
last_seq = 11797
current_ts = 274.284302
current_received_ts = 274.283691
current_seq = 11798
count = 21
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.268066/11797, current 274.284302/11798: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.284302
last_received_ts = 274.283691
last_seq = 11798
current_ts = 274.300568
current_received_ts = 274.299957
current_seq = 11799
count = 22
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.284302/11798, current 274.300568/11799: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.300568
last_received_ts = 274.299957
last_seq = 11799
current_ts = 274.316803
current_received_ts = 274.316223
current_seq = 11800
count = 23
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.300568/11799, current 274.316803/11800: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.316803
last_received_ts = 274.316223
last_seq = 11800
current_ts = 274.333069
current_received_ts = 274.332458
current_seq = 11801
count = 24
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.316803/11800, current 274.333069/11801: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.333069
last_received_ts = 274.332458
last_seq = 11801
current_ts = 274.349335
current_received_ts = 274.348724
current_seq = 11802
count = 25
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.333069/11801, current 274.349335/11802: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.349335
last_received_ts = 274.348724
last_seq = 11802
current_ts = 274.365570
current_received_ts = 274.364960
current_seq = 11803
count = 26
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.349335/11802, current 274.365570/11803: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.365570
last_received_ts = 274.364960
last_seq = 11803
current_ts = 274.381836
current_received_ts = 274.381226
current_seq = 11804
count = 27
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.365570/11803, current 274.381836/11804: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.381836
last_received_ts = 274.381226
last_seq = 11804
current_ts = 274.398071
current_received_ts = 274.397461
current_seq = 11805
count = 28
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.381836/11804, current 274.398071/11805: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.398071
last_received_ts = 274.397461
last_seq = 11805
current_ts = 274.414337
current_received_ts = 274.413727
current_seq = 11806
count = 29
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.398071/11805, current 274.414337/11806: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.414337
last_received_ts = 274.413727
last_seq = 11806
current_ts = 274.430603
current_received_ts = 274.429993
current_seq = 11807
count = 30
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.414337/11806, current 274.430603/11807: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.430603
last_received_ts = 274.429993
last_seq = 11807
current_ts = 274.446838
current_received_ts = 274.446228
current_seq = 11808
count = 31
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.430603/11807, current 274.446838/11808: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.446838
last_received_ts = 274.446228
last_seq = 11808
current_ts = 274.463104
current_received_ts = 274.462494
current_seq = 11809
count = 32
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.446838/11808, current 274.463104/11809: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.463104
last_received_ts = 274.462494
last_seq = 11809
current_ts = 274.479340
current_received_ts = 274.478729
current_seq = 11810
count = 33
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.463104/11809, current 274.479340/11810: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.479340
last_received_ts = 274.478729
last_seq = 11810
current_ts = 274.495605
current_received_ts = 274.494995
current_seq = 11811
count = 34
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.479340/11810, current 274.495605/11811: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.495605
last_received_ts = 274.494995
last_seq = 11811
current_ts = 274.511871
current_received_ts = 274.511261
current_seq = 11812
count = 35
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.495605/11811, current 274.511871/11812: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.511871
last_received_ts = 274.511261
last_seq = 11812
current_ts = 274.528107
current_received_ts = 274.527496
current_seq = 11813
count = 36
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.511871/11812, current 274.528107/11813: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.528107
last_received_ts = 274.527496
last_seq = 11813
current_ts = 274.544373
current_received_ts = 274.543762
current_seq = 11814
count = 37
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.528107/11813, current 274.544373/11814: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.544373
last_received_ts = 274.543762
last_seq = 11814
current_ts = 274.560608
current_received_ts = 274.560059
current_seq = 11815
count = 38
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.544373/11814, current 274.560608/11815: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.560608
last_received_ts = 274.560059
last_seq = 11815
current_ts = 274.576874
current_received_ts = 274.576263
current_seq = 11816
count = 39
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.560608/11815, current 274.576874/11816: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.576874
last_received_ts = 274.576263
last_seq = 11816
current_ts = 274.593109
current_received_ts = 274.592499
current_seq = 11817
count = 40
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.576874/11816, current 274.593109/11817: elapsed=16252.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.593109
last_received_ts = 274.592499
last_seq = 11817
current_ts = 274.609375
current_received_ts = 274.608765
current_seq = 11818
count = 41
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.593109/11817, current 274.609375/11818: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.609375
last_received_ts = 274.608765
last_seq = 11818
current_ts = 274.625641
current_received_ts = 274.625031
current_seq = 11819
count = 42
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.609375/11818, current 274.625641/11819: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.625641
last_received_ts = 274.625031
last_seq = 11819
current_ts = 274.641876
current_received_ts = 274.641266
current_seq = 11820
count = 43
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.625641/11819, current 274.641876/11820: elapsed=16252.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.641876
last_received_ts = 274.641266
last_seq = 11820
current_ts = 274.658142
current_received_ts = 274.657532
current_seq = 11821
count = 44
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.641876/11820, current 274.658142/11821: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.658142
last_received_ts = 274.657532
last_seq = 11821
current_ts = 274.674377
current_received_ts = 274.673798
current_seq = 11822
count = 45
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.658142/11821, current 274.674377/11822: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.674377
last_received_ts = 274.673798
last_seq = 11822
current_ts = 274.690643
current_received_ts = 274.690033
current_seq = 11823
count = 46
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.674377/11822, current 274.690643/11823: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.690643
last_received_ts = 274.690033
last_seq = 11823
current_ts = 274.706909
current_received_ts = 274.706299
current_seq = 11824
count = 47
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.690643/11823, current 274.706909/11824: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.706909
last_received_ts = 274.706299
last_seq = 11824
current_ts = 274.723145
current_received_ts = 274.722565
current_seq = 11825
count = 48
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.706909/11824, current 274.723145/11825: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.723145
last_received_ts = 274.722565
last_seq = 11825
current_ts = 274.739410
current_received_ts = 274.738800
current_seq = 11826
count = 49
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.723145/11825, current 274.739410/11826: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.739410
last_received_ts = 274.738800
last_seq = 11826
current_ts = 274.755646
current_received_ts = 274.755096
current_seq = 11827
count = 50
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.739410/11826, current 274.755646/11827: elapsed=16255.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.755646
last_received_ts = 274.755096
last_seq = 11827
current_ts = 274.771912
current_received_ts = 274.771301
current_seq = 11828
count = 51
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.755646/11827, current 274.771912/11828: elapsed=16252.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.771912
last_received_ts = 274.771301
last_seq = 11828
current_ts = 274.788177
current_received_ts = 274.787567
current_seq = 11829
count = 52
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.771912/11828, current 274.788177/11829: elapsed=16252.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.788177
last_received_ts = 274.787567
last_seq = 11829
current_ts = 274.804413
current_received_ts = 274.803802
current_seq = 11830
count = 53
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.788177/11829, current 274.804413/11830: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.804413
last_received_ts = 274.803802
last_seq = 11830
current_ts = 274.820679
current_received_ts = 274.820068
current_seq = 11831
count = 54
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.804413/11830, current 274.820679/11831: elapsed=16261.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.820679
last_received_ts = 274.820068
last_seq = 11831
current_ts = 274.836914
current_received_ts = 274.836304
current_seq = 11832
count = 55
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.820679/11831, current 274.836914/11832: elapsed=16245.0us expected=16195.3us +- 81.0us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.836914
last_received_ts = 274.836304
last_seq = 11832
current_ts = 274.853180
current_received_ts = 274.852570
current_seq = 11833
count = 56
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.836914/11832, current 274.853180/11833: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.853180
last_received_ts = 274.852570
last_seq = 11833
current_ts = 274.869446
current_received_ts = 274.868835
current_seq = 11834
count = 57
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.853180/11833, current 274.869446/11834: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.869446
last_received_ts = 274.868835
last_seq = 11834
current_ts = 274.885681
current_received_ts = 274.885071
current_seq = 11835
count = 58
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.869446/11834, current 274.885681/11835: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.885681
last_received_ts = 274.885071
last_seq = 11835
current_ts = 274.901947
current_received_ts = 274.901337
current_seq = 11836
count = 59
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.885681/11835, current 274.901947/11836: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.901947
last_received_ts = 274.901337
last_seq = 11836
current_ts = 274.918182
current_received_ts = 274.917572
current_seq = 11837
count = 60
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.901947/11836, current 274.918182/11837: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.918182
last_received_ts = 274.917572
last_seq = 11837
current_ts = 274.934448
current_received_ts = 274.933838
current_seq = 11838
count = 61
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.918182/11837, current 274.934448/11838: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.934448
last_received_ts = 274.933838
last_seq = 11838
current_ts = 274.950684
current_received_ts = 274.950104
current_seq = 11839
count = 62
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.934448/11838, current 274.950684/11839: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.950684
last_received_ts = 274.950104
last_seq = 11839
current_ts = 274.966949
current_received_ts = 274.966339
current_seq = 11840
count = 63
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.950684/11839, current 274.966949/11840: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.966949
last_received_ts = 274.966339
last_seq = 11840
current_ts = 274.983215
current_received_ts = 274.982605
current_seq = 11841
count = 64
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.966949/11840, current 274.983215/11841: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.983215
last_received_ts = 274.982605
last_seq = 11841
current_ts = 274.999451
current_received_ts = 274.998871
current_seq = 11842
count = 65
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.983215/11841, current 274.999451/11842: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 274.999451
last_received_ts = 274.998871
last_seq = 11842
current_ts = 275.015717
current_received_ts = 275.015106
current_seq = 11843
count = 66
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 274.999451/11842, current 275.015717/11843: elapsed=16256.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.015717
last_received_ts = 275.015106
last_seq = 11843
current_ts = 275.031952
current_received_ts = 275.031372
current_seq = 11844
count = 67
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.015717/11843, current 275.031952/11844: elapsed=16251.0us expected=16195.3us +- 81.0us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.031952
last_received_ts = 275.031372
last_seq = 11844
current_ts = 275.048218
current_received_ts = 275.047607
current_seq = 11845
count = 68
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.031952/11844, current 275.048218/11845: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.048218
last_received_ts = 275.047607
last_seq = 11845
current_ts = 275.064484
current_received_ts = 275.063904
current_seq = 11846
count = 69
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.048218/11845, current 275.064484/11846: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.064484
last_received_ts = 275.063904
last_seq = 11846
current_ts = 275.080719
current_received_ts = 275.080109
current_seq = 11847
count = 70
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.064484/11846, current 275.080719/11847: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.080719
last_received_ts = 275.080109
last_seq = 11847
current_ts = 275.096985
current_received_ts = 275.096375
current_seq = 11848
count = 71
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.080719/11847, current 275.096985/11848: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.096985
last_received_ts = 275.096375
last_seq = 11848
current_ts = 275.113220
current_received_ts = 275.112640
current_seq = 11849
count = 72
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.096985/11848, current 275.113220/11849: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.113220
last_received_ts = 275.112640
last_seq = 11849
current_ts = 275.129486
current_received_ts = 275.128876
current_seq = 11850
count = 73
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.113220/11849, current 275.129486/11850: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.129486
last_received_ts = 275.128876
last_seq = 11850
current_ts = 275.145752
current_received_ts = 275.145142
current_seq = 11851
count = 74
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.129486/11850, current 275.145752/11851: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.145752
last_received_ts = 275.145142
last_seq = 11851
current_ts = 275.161987
current_received_ts = 275.161377
current_seq = 11852
count = 75
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.145752/11851, current 275.161987/11852: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.161987
last_received_ts = 275.161377
last_seq = 11852
current_ts = 275.178253
current_received_ts = 275.177673
current_seq = 11853
count = 76
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.161987/11852, current 275.178253/11853: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.178253
last_received_ts = 275.177673
last_seq = 11853
current_ts = 275.194489
current_received_ts = 275.193909
current_seq = 11854
count = 77
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.178253/11853, current 275.194489/11854: elapsed=16253.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.194489
last_received_ts = 275.193909
last_seq = 11854
current_ts = 275.210754
current_received_ts = 275.210144
current_seq = 11855
count = 78
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.194489/11854, current 275.210754/11855: elapsed=16254.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.210754
last_received_ts = 275.210144
last_seq = 11855
current_ts = 275.227020
current_received_ts = 275.226440
current_seq = 11856
count = 79
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.210754/11855, current 275.227020/11856: elapsed=16268.0us expected=16195.3us +- 81.0us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 275.227020
last_received_ts = 275.226440
last_seq = 11856
current_ts = 275.243317
current_received_ts = 275.242859
current_seq = 11857
count = 80
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 275.227020/11856, current 275.243317/11857: elapsed=16303.0us expected=16195.3us +- 81.0us, error 0.7%
(kms_flip:7572) DEBUG: inconsistent flip ts/seq: last 275.227020/11856, current 275.243317/11857: elapsed=16303.0us expected=16195.3us
(kms_flip:7572) DEBUG: expected 8296, counted 80, encoder type 2
(kms_flip:7572) DEBUG: dropped frames, expected 8296, counted 80, encoder type 2
(kms_flip:7572) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7572) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7572) igt_core-INFO: Stack trace:
(kms_flip:7572) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7572) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7572) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7572) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7572) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7572) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7572) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7572) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (5.045s)
Starting dynamic subtest: AD-DP2-HDMI-A3
(kms_flip:7572) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7572) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AD-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7572) DEBUG: flip ts/seq: last 279.294128/12088, current 279.310577/12089: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.310577
last_received_ts = 279.309967
last_seq = 12089
current_ts = 279.327026
current_received_ts = 279.327057
current_seq = 12090
count = 25
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.310577/12089, current 279.327026/12090: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.327026
last_received_ts = 279.327057
last_seq = 12090
current_ts = 279.343506
current_received_ts = 279.342865
current_seq = 12091
count = 26
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.327026/12090, current 279.343506/12091: elapsed=16451.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.343506
last_received_ts = 279.342865
last_seq = 12091
current_ts = 279.359955
current_received_ts = 279.359344
current_seq = 12092
count = 27
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.343506/12091, current 279.359955/12092: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.359955
last_received_ts = 279.359344
last_seq = 12092
current_ts = 279.376404
current_received_ts = 279.375793
current_seq = 12093
count = 28
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.359955/12092, current 279.376404/12093: elapsed=16451.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.376404
last_received_ts = 279.375793
last_seq = 12093
current_ts = 279.392853
current_received_ts = 279.392242
current_seq = 12094
count = 29
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.376404/12093, current 279.392853/12094: elapsed=16451.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.392853
last_received_ts = 279.392242
last_seq = 12094
current_ts = 279.409302
current_received_ts = 279.409058
current_seq = 12095
count = 30
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.392853/12094, current 279.409302/12095: elapsed=16445.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.409302
last_received_ts = 279.409058
last_seq = 12095
current_ts = 279.425751
current_received_ts = 279.425140
current_seq = 12096
count = 31
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.409302/12095, current 279.425751/12096: elapsed=16457.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.425751
last_received_ts = 279.425140
last_seq = 12096
current_ts = 279.442200
current_received_ts = 279.441589
current_seq = 12097
count = 32
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.425751/12096, current 279.442200/12097: elapsed=16455.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.442200
last_received_ts = 279.441589
last_seq = 12097
current_ts = 279.458649
current_received_ts = 279.458069
current_seq = 12098
count = 33
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.442200/12097, current 279.458649/12098: elapsed=16451.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.458649
last_received_ts = 279.458069
last_seq = 12098
current_ts = 279.475098
current_received_ts = 279.474487
current_seq = 12099
count = 34
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.458649/12098, current 279.475098/12099: elapsed=16447.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.475098
last_received_ts = 279.474487
last_seq = 12099
current_ts = 279.491547
current_received_ts = 279.490967
current_seq = 12100
count = 35
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.475098/12099, current 279.491547/12100: elapsed=16455.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.491547
last_received_ts = 279.490967
last_seq = 12100
current_ts = 279.507996
current_received_ts = 279.507385
current_seq = 12101
count = 36
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.491547/12100, current 279.507996/12101: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.507996
last_received_ts = 279.507385
last_seq = 12101
current_ts = 279.524445
current_received_ts = 279.523834
current_seq = 12102
count = 37
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.507996/12101, current 279.524445/12102: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.524445
last_received_ts = 279.523834
last_seq = 12102
current_ts = 279.540894
current_received_ts = 279.541046
current_seq = 12103
count = 38
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.524445/12102, current 279.540894/12103: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.540894
last_received_ts = 279.541046
last_seq = 12103
current_ts = 279.557343
current_received_ts = 279.556732
current_seq = 12104
count = 39
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.540894/12103, current 279.557343/12104: elapsed=16455.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.557343
last_received_ts = 279.556732
last_seq = 12104
current_ts = 279.573792
current_received_ts = 279.573212
current_seq = 12105
count = 40
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.557343/12104, current 279.573792/12105: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.573792
last_received_ts = 279.573212
last_seq = 12105
current_ts = 279.590271
current_received_ts = 279.589661
current_seq = 12106
count = 41
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.573792/12105, current 279.590271/12106: elapsed=16454.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.590271
last_received_ts = 279.589661
last_seq = 12106
current_ts = 279.606689
current_received_ts = 279.606842
current_seq = 12107
count = 42
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.590271/12106, current 279.606689/12107: elapsed=16439.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.606689
last_received_ts = 279.606842
last_seq = 12107
current_ts = 279.623169
current_received_ts = 279.623413
current_seq = 12108
count = 43
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.606689/12107, current 279.623169/12108: elapsed=16463.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.623169
last_received_ts = 279.623413
last_seq = 12108
current_ts = 279.639618
current_received_ts = 279.639862
current_seq = 12109
count = 44
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.623169/12108, current 279.639618/12109: elapsed=16447.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.639618
last_received_ts = 279.639862
last_seq = 12109
current_ts = 279.656067
current_received_ts = 279.656219
current_seq = 12110
count = 45
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.639618/12109, current 279.656067/12110: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.656067
last_received_ts = 279.656219
last_seq = 12110
current_ts = 279.672485
current_received_ts = 279.672668
current_seq = 12111
count = 46
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.656067/12110, current 279.672485/12111: elapsed=16444.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.672485
last_received_ts = 279.672668
last_seq = 12111
current_ts = 279.688965
current_received_ts = 279.689056
current_seq = 12112
count = 47
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.672485/12111, current 279.688965/12112: elapsed=16462.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.688965
last_received_ts = 279.689056
last_seq = 12112
current_ts = 279.705414
current_received_ts = 279.705261
current_seq = 12113
count = 48
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.688965/12112, current 279.705414/12113: elapsed=16453.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.705414
last_received_ts = 279.705261
last_seq = 12113
current_ts = 279.721863
current_received_ts = 279.721985
current_seq = 12114
count = 49
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.705414/12113, current 279.721863/12114: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.721863
last_received_ts = 279.721985
last_seq = 12114
current_ts = 279.738312
current_received_ts = 279.738068
current_seq = 12115
count = 50
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.721863/12114, current 279.738312/12115: elapsed=16445.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.738312
last_received_ts = 279.738068
last_seq = 12115
current_ts = 279.754761
current_received_ts = 279.754150
current_seq = 12116
count = 51
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.738312/12115, current 279.754761/12116: elapsed=16459.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.754761
last_received_ts = 279.754150
last_seq = 12116
current_ts = 279.771210
current_received_ts = 279.771057
current_seq = 12117
count = 52
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.754761/12116, current 279.771210/12117: elapsed=16449.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.771210
last_received_ts = 279.771057
last_seq = 12117
current_ts = 279.787659
current_received_ts = 279.787811
current_seq = 12118
count = 53
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.771210/12117, current 279.787659/12118: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.787659
last_received_ts = 279.787811
last_seq = 12118
current_ts = 279.804108
current_received_ts = 279.804047
current_seq = 12119
count = 54
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.787659/12118, current 279.804108/12119: elapsed=16446.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.804108
last_received_ts = 279.804047
last_seq = 12119
current_ts = 279.820557
current_received_ts = 279.820709
current_seq = 12120
count = 55
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.804108/12119, current 279.820557/12120: elapsed=16455.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.820557
last_received_ts = 279.820709
last_seq = 12120
current_ts = 279.837036
current_received_ts = 279.837067
current_seq = 12121
count = 56
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.820557/12120, current 279.837036/12121: elapsed=16458.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.837036
last_received_ts = 279.837067
last_seq = 12121
current_ts = 279.853485
current_received_ts = 279.852875
current_seq = 12122
count = 57
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.837036/12121, current 279.853485/12122: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.853485
last_received_ts = 279.852875
last_seq = 12122
current_ts = 279.869934
current_received_ts = 279.869324
current_seq = 12123
count = 58
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.853485/12122, current 279.869934/12123: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.869934
last_received_ts = 279.869324
last_seq = 12123
current_ts = 279.886383
current_received_ts = 279.885773
current_seq = 12124
count = 59
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.869934/12123, current 279.886383/12124: elapsed=16454.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.886383
last_received_ts = 279.885773
last_seq = 12124
current_ts = 279.902832
current_received_ts = 279.902405
current_seq = 12125
count = 60
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.886383/12124, current 279.902832/12125: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.902832
last_received_ts = 279.902405
last_seq = 12125
current_ts = 279.919281
current_received_ts = 279.918671
current_seq = 12126
count = 61
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.902832/12125, current 279.919281/12126: elapsed=16449.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.919281
last_received_ts = 279.918671
last_seq = 12126
current_ts = 279.935730
current_received_ts = 279.935150
current_seq = 12127
count = 62
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.919281/12126, current 279.935730/12127: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.935730
last_received_ts = 279.935150
last_seq = 12127
current_ts = 279.952179
current_received_ts = 279.951599
current_seq = 12128
count = 63
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.935730/12127, current 279.952179/12128: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.952179
last_received_ts = 279.951599
last_seq = 12128
current_ts = 279.968628
current_received_ts = 279.968048
current_seq = 12129
count = 64
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.952179/12128, current 279.968628/12129: elapsed=16454.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.968628
last_received_ts = 279.968048
last_seq = 12129
current_ts = 279.985077
current_received_ts = 279.984467
current_seq = 12130
count = 65
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.968628/12129, current 279.985077/12130: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 279.985077
last_received_ts = 279.984467
last_seq = 12130
current_ts = 280.001526
current_received_ts = 280.000916
current_seq = 12131
count = 66
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 279.985077/12130, current 280.001526/12131: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.001526
last_received_ts = 280.000916
last_seq = 12131
current_ts = 280.017975
current_received_ts = 280.017365
current_seq = 12132
count = 67
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.001526/12131, current 280.017975/12132: elapsed=16450.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.017975
last_received_ts = 280.017365
last_seq = 12132
current_ts = 280.034424
current_received_ts = 280.033844
current_seq = 12133
count = 68
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.017975/12132, current 280.034424/12133: elapsed=16453.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.034424
last_received_ts = 280.033844
last_seq = 12133
current_ts = 280.050903
current_received_ts = 280.050293
current_seq = 12134
count = 69
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.034424/12133, current 280.050903/12134: elapsed=16452.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.050903
last_received_ts = 280.050293
last_seq = 12134
current_ts = 280.067322
current_received_ts = 280.067047
current_seq = 12135
count = 70
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.050903/12134, current 280.067322/12135: elapsed=16441.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.067322
last_received_ts = 280.067047
last_seq = 12135
current_ts = 280.083771
current_received_ts = 280.083923
current_seq = 12136
count = 71
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.067322/12135, current 280.083771/12136: elapsed=16447.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.083771
last_received_ts = 280.083923
last_seq = 12136
current_ts = 280.100220
current_received_ts = 280.100067
current_seq = 12137
count = 72
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.083771/12136, current 280.100220/12137: elapsed=16454.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.100220
last_received_ts = 280.100067
last_seq = 12137
current_ts = 280.116669
current_received_ts = 280.116821
current_seq = 12138
count = 73
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.100220/12137, current 280.116669/12138: elapsed=16448.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.116669
last_received_ts = 280.116821
last_seq = 12138
current_ts = 280.133148
current_received_ts = 280.132538
current_seq = 12139
count = 74
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.116669/12138, current 280.133148/12139: elapsed=16464.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.133148
last_received_ts = 280.132538
last_seq = 12139
current_ts = 280.149597
current_received_ts = 280.148987
current_seq = 12140
count = 75
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.133148/12139, current 280.149597/12140: elapsed=16451.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.149597
last_received_ts = 280.148987
last_seq = 12140
current_ts = 280.166046
current_received_ts = 280.166046
current_seq = 12141
count = 76
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.149597/12140, current 280.166046/12141: elapsed=16449.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.166046
last_received_ts = 280.166046
last_seq = 12141
current_ts = 280.182495
current_received_ts = 280.182617
current_seq = 12142
count = 77
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.166046/12141, current 280.182495/12142: elapsed=16443.0us expected=16421.2us +- 82.1us, error 0.1%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.182495
last_received_ts = 280.182617
last_seq = 12142
current_ts = 280.198944
current_received_ts = 280.199066
current_seq = 12143
count = 78
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.182495/12142, current 280.198944/12143: elapsed=16458.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.198944
last_received_ts = 280.199066
last_seq = 12143
current_ts = 280.215393
current_received_ts = 280.215088
current_seq = 12144
count = 79
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.198944/12143, current 280.215393/12144: elapsed=16453.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.215393
last_received_ts = 280.215088
last_seq = 12144
current_ts = 280.231842
current_received_ts = 280.232056
current_seq = 12145
count = 80
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.215393/12144, current 280.231842/12145: elapsed=16458.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.231842
last_received_ts = 280.232056
last_seq = 12145
current_ts = 280.248352
current_received_ts = 280.248077
current_seq = 12146
count = 81
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.231842/12145, current 280.248352/12146: elapsed=16483.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.248352
last_received_ts = 280.248077
last_seq = 12146
current_ts = 280.264801
current_received_ts = 280.264191
current_seq = 12147
count = 82
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.248352/12146, current 280.264801/12147: elapsed=16478.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.264801
last_received_ts = 280.264191
last_seq = 12147
current_ts = 280.281281
current_received_ts = 280.281219
current_seq = 12148
count = 83
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.264801/12147, current 280.281281/12148: elapsed=16475.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.281281
last_received_ts = 280.281219
last_seq = 12148
current_ts = 280.297760
current_received_ts = 280.297882
current_seq = 12149
count = 84
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.281281/12148, current 280.297760/12149: elapsed=16471.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.297760
last_received_ts = 280.297882
last_seq = 12149
current_ts = 280.314240
current_received_ts = 280.314056
current_seq = 12150
count = 85
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.297760/12149, current 280.314240/12150: elapsed=16484.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.314240
last_received_ts = 280.314056
last_seq = 12150
current_ts = 280.330719
current_received_ts = 280.330841
current_seq = 12151
count = 86
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.314240/12150, current 280.330719/12151: elapsed=16475.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.330719
last_received_ts = 280.330841
last_seq = 12151
current_ts = 280.347198
current_received_ts = 280.346588
current_seq = 12152
count = 87
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.330719/12151, current 280.347198/12152: elapsed=16483.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.347198
last_received_ts = 280.346588
last_seq = 12152
current_ts = 280.363678
current_received_ts = 280.363068
current_seq = 12153
count = 88
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.347198/12152, current 280.363678/12153: elapsed=16474.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.363678
last_received_ts = 280.363068
last_seq = 12153
current_ts = 280.380157
current_received_ts = 280.380066
current_seq = 12154
count = 89
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.363678/12153, current 280.380157/12154: elapsed=16477.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.380157
last_received_ts = 280.380066
last_seq = 12154
current_ts = 280.396637
current_received_ts = 280.396790
current_seq = 12155
count = 90
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.380157/12154, current 280.396637/12155: elapsed=16476.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.396637
last_received_ts = 280.396790
last_seq = 12155
current_ts = 280.413116
current_received_ts = 280.412506
current_seq = 12156
count = 91
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.396637/12155, current 280.413116/12156: elapsed=16479.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.413116
last_received_ts = 280.412506
last_seq = 12156
current_ts = 280.429596
current_received_ts = 280.429718
current_seq = 12157
count = 92
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.413116/12156, current 280.429596/12157: elapsed=16472.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.429596
last_received_ts = 280.429718
last_seq = 12157
current_ts = 280.446075
current_received_ts = 280.446045
current_seq = 12158
count = 93
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.429596/12157, current 280.446075/12158: elapsed=16481.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.446075
last_received_ts = 280.446045
last_seq = 12158
current_ts = 280.462524
current_received_ts = 280.462677
current_seq = 12159
count = 94
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.446075/12158, current 280.462524/12159: elapsed=16466.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.462524
last_received_ts = 280.462677
last_seq = 12159
current_ts = 280.479004
current_received_ts = 280.478394
current_seq = 12160
count = 95
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.462524/12159, current 280.479004/12160: elapsed=16489.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.479004
last_received_ts = 280.478394
last_seq = 12160
current_ts = 280.495483
current_received_ts = 280.495056
current_seq = 12161
count = 96
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.479004/12160, current 280.495483/12161: elapsed=16480.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.495483
last_received_ts = 280.495056
last_seq = 12161
current_ts = 280.511963
current_received_ts = 280.512115
current_seq = 12162
count = 97
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.495483/12161, current 280.511963/12162: elapsed=16470.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.511963
last_received_ts = 280.512115
last_seq = 12162
current_ts = 280.528442
current_received_ts = 280.527832
current_seq = 12163
count = 98
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.511963/12162, current 280.528442/12163: elapsed=16482.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.528442
last_received_ts = 280.527832
last_seq = 12163
current_ts = 280.544922
current_received_ts = 280.545074
current_seq = 12164
count = 99
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.528442/12163, current 280.544922/12164: elapsed=16467.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.544922
last_received_ts = 280.545074
last_seq = 12164
current_ts = 280.561401
current_received_ts = 280.561066
current_seq = 12165
count = 100
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.544922/12164, current 280.561401/12165: elapsed=16489.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.561401
last_received_ts = 280.561066
last_seq = 12165
current_ts = 280.577881
current_received_ts = 280.577271
current_seq = 12166
count = 101
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.561401/12165, current 280.577881/12166: elapsed=16474.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.577881
last_received_ts = 280.577271
last_seq = 12166
current_ts = 280.594360
current_received_ts = 280.594055
current_seq = 12167
count = 102
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.577881/12166, current 280.594360/12167: elapsed=16472.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.594360
last_received_ts = 280.594055
last_seq = 12167
current_ts = 280.610840
current_received_ts = 280.610962
current_seq = 12168
count = 103
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.594360/12167, current 280.610840/12168: elapsed=16479.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.610840
last_received_ts = 280.610962
last_seq = 12168
current_ts = 280.627319
current_received_ts = 280.626801
current_seq = 12169
count = 104
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.610840/12168, current 280.627319/12169: elapsed=16481.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.627319
last_received_ts = 280.626801
last_seq = 12169
current_ts = 280.643799
current_received_ts = 280.643250
current_seq = 12170
count = 105
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.627319/12169, current 280.643799/12170: elapsed=16475.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.643799
last_received_ts = 280.643250
last_seq = 12170
current_ts = 280.660248
current_received_ts = 280.659943
current_seq = 12171
count = 106
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.643799/12170, current 280.660248/12171: elapsed=16476.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.660248
last_received_ts = 280.659943
last_seq = 12171
current_ts = 280.676758
current_received_ts = 280.676147
current_seq = 12172
count = 107
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.660248/12171, current 280.676758/12172: elapsed=16480.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.676758
last_received_ts = 280.676147
last_seq = 12172
current_ts = 280.693207
current_received_ts = 280.693085
current_seq = 12173
count = 108
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.676758/12172, current 280.693207/12173: elapsed=16474.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.693207
last_received_ts = 280.693085
last_seq = 12173
current_ts = 280.709686
current_received_ts = 280.709106
current_seq = 12174
count = 109
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.693207/12173, current 280.709686/12174: elapsed=16480.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.709686
last_received_ts = 280.709106
last_seq = 12174
current_ts = 280.726166
current_received_ts = 280.725555
current_seq = 12175
count = 110
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.709686/12174, current 280.726166/12175: elapsed=16479.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.726166
last_received_ts = 280.725555
last_seq = 12175
current_ts = 280.742645
current_received_ts = 280.742126
current_seq = 12176
count = 111
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.726166/12175, current 280.742645/12176: elapsed=16471.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.742645
last_received_ts = 280.742126
last_seq = 12176
current_ts = 280.759125
current_received_ts = 280.758575
current_seq = 12177
count = 112
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.742645/12176, current 280.759125/12177: elapsed=16490.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.759125
last_received_ts = 280.758575
last_seq = 12177
current_ts = 280.775604
current_received_ts = 280.775085
current_seq = 12178
count = 113
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.759125/12177, current 280.775604/12178: elapsed=16472.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.775604
last_received_ts = 280.775085
last_seq = 12178
current_ts = 280.792084
current_received_ts = 280.791534
current_seq = 12179
count = 114
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.775604/12178, current 280.792084/12179: elapsed=16475.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.792084
last_received_ts = 280.791534
last_seq = 12179
current_ts = 280.808563
current_received_ts = 280.808044
current_seq = 12180
count = 115
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.792084/12179, current 280.808563/12180: elapsed=16483.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.808563
last_received_ts = 280.808044
last_seq = 12180
current_ts = 280.825012
current_received_ts = 280.825073
current_seq = 12181
count = 116
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.808563/12180, current 280.825012/12181: elapsed=16457.0us expected=16421.2us +- 82.1us, error 0.2%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.825012
last_received_ts = 280.825073
last_seq = 12181
current_ts = 280.841522
current_received_ts = 280.841736
current_seq = 12182
count = 117
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.825012/12181, current 280.841522/12182: elapsed=16489.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.841522
last_received_ts = 280.841736
last_seq = 12182
current_ts = 280.858002
current_received_ts = 280.857452
current_seq = 12183
count = 118
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.841522/12182, current 280.858002/12183: elapsed=16478.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.858002
last_received_ts = 280.857452
last_seq = 12183
current_ts = 280.874451
current_received_ts = 280.874695
current_seq = 12184
count = 119
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.858002/12183, current 280.874451/12184: elapsed=16464.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.874451
last_received_ts = 280.874695
last_seq = 12184
current_ts = 280.890930
current_received_ts = 280.891083
current_seq = 12185
count = 120
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.874451/12184, current 280.890930/12185: elapsed=16477.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.890930
last_received_ts = 280.891083
last_seq = 12185
current_ts = 280.907410
current_received_ts = 280.907623
current_seq = 12186
count = 121
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.890930/12185, current 280.907410/12186: elapsed=16487.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.907410
last_received_ts = 280.907623
last_seq = 12186
current_ts = 280.923889
current_received_ts = 280.923370
current_seq = 12187
count = 122
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.907410/12186, current 280.923889/12187: elapsed=16476.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.923889
last_received_ts = 280.923370
last_seq = 12187
current_ts = 280.940369
current_received_ts = 280.940582
current_seq = 12188
count = 123
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.923889/12187, current 280.940369/12188: elapsed=16470.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.940369
last_received_ts = 280.940582
last_seq = 12188
current_ts = 280.956848
current_received_ts = 280.956329
current_seq = 12189
count = 124
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.940369/12188, current 280.956848/12189: elapsed=16488.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.956848
last_received_ts = 280.956329
last_seq = 12189
current_ts = 280.973328
current_received_ts = 280.972778
current_seq = 12190
count = 125
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.956848/12189, current 280.973328/12190: elapsed=16477.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.973328
last_received_ts = 280.972778
last_seq = 12190
current_ts = 280.989807
current_received_ts = 280.989288
current_seq = 12191
count = 126
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.973328/12190, current 280.989807/12191: elapsed=16476.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 280.989807
last_received_ts = 280.989288
last_seq = 12191
current_ts = 281.006287
current_received_ts = 281.006073
current_seq = 12192
count = 127
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 280.989807/12191, current 281.006287/12192: elapsed=16476.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.006287
last_received_ts = 281.006073
last_seq = 12192
current_ts = 281.022766
current_received_ts = 281.022217
current_seq = 12193
count = 128
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.006287/12192, current 281.022766/12193: elapsed=16487.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.022766
last_received_ts = 281.022217
last_seq = 12193
current_ts = 281.039246
current_received_ts = 281.039093
current_seq = 12194
count = 129
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.022766/12193, current 281.039246/12194: elapsed=16468.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.039246
last_received_ts = 281.039093
last_seq = 12194
current_ts = 281.055695
current_received_ts = 281.055908
current_seq = 12195
count = 130
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.039246/12194, current 281.055695/12195: elapsed=16466.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.055695
last_received_ts = 281.055908
last_seq = 12195
current_ts = 281.072205
current_received_ts = 281.071655
current_seq = 12196
count = 131
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.055695/12195, current 281.072205/12196: elapsed=16493.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.072205
last_received_ts = 281.071655
last_seq = 12196
current_ts = 281.088654
current_received_ts = 281.088898
current_seq = 12197
count = 132
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.072205/12196, current 281.088654/12197: elapsed=16464.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.088654
last_received_ts = 281.088898
last_seq = 12197
current_ts = 281.105133
current_received_ts = 281.105347
current_seq = 12198
count = 133
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.088654/12197, current 281.105133/12198: elapsed=16483.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.105133
last_received_ts = 281.105347
last_seq = 12198
current_ts = 281.121613
current_received_ts = 281.121826
current_seq = 12199
count = 134
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.105133/12198, current 281.121613/12199: elapsed=16469.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.121613
last_received_ts = 281.121826
last_seq = 12199
current_ts = 281.138123
current_received_ts = 281.137543
current_seq = 12200
count = 135
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.121613/12199, current 281.138123/12200: elapsed=16496.0us expected=16421.2us +- 82.1us, error 0.5%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.138123
last_received_ts = 281.137543
last_seq = 12200
current_ts = 281.154572
current_received_ts = 281.154785
current_seq = 12201
count = 136
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.138123/12200, current 281.154572/12201: elapsed=16463.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.154572
last_received_ts = 281.154785
last_seq = 12201
current_ts = 281.171051
current_received_ts = 281.171112
current_seq = 12202
count = 137
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.154572/12201, current 281.171051/12202: elapsed=16485.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.171051
last_received_ts = 281.171112
last_seq = 12202
current_ts = 281.187531
current_received_ts = 281.187500
current_seq = 12203
count = 138
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.171051/12202, current 281.187531/12203: elapsed=16472.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.187531
last_received_ts = 281.187500
last_seq = 12203
current_ts = 281.204010
current_received_ts = 281.203400
current_seq = 12204
count = 139
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.187531/12203, current 281.204010/12204: elapsed=16481.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.204010
last_received_ts = 281.203400
last_seq = 12204
current_ts = 281.220490
current_received_ts = 281.220215
current_seq = 12205
count = 140
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.204010/12204, current 281.220490/12205: elapsed=16473.0us expected=16421.2us +- 82.1us, error 0.3%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.220490
last_received_ts = 281.220215
last_seq = 12205
current_ts = 281.236969
current_received_ts = 281.236420
current_seq = 12206
count = 141
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.220490/12205, current 281.236969/12206: elapsed=16502.0us expected=16421.2us +- 82.1us, error 0.5%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.236969
last_received_ts = 281.236420
last_seq = 12206
current_ts = 281.253479
current_received_ts = 281.252991
current_seq = 12207
count = 142
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.236969/12206, current 281.253479/12207: elapsed=16496.0us expected=16421.2us +- 82.1us, error 0.5%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.253479
last_received_ts = 281.252991
last_seq = 12207
current_ts = 281.269989
current_received_ts = 281.269836
current_seq = 12208
count = 143
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.253479/12207, current 281.269989/12208: elapsed=16494.0us expected=16421.2us +- 82.1us, error 0.4%
(kms_flip:7572) DEBUG: name = flip
last_ts = 281.269989
last_received_ts = 281.269836
last_seq = 12208
current_ts = 281.286499
current_received_ts = 281.286438
current_seq = 12209
count = 144
seq_step = 1
(kms_flip:7572) DEBUG: flip ts/seq: last 281.269989/12208, current 281.286499/12209: elapsed=16511.0us expected=16421.2us +- 82.1us, error 0.5%
(kms_flip:7572) DEBUG: inconsistent flip ts/seq: last 281.269989/12208, current 281.286499/12209: elapsed=16511.0us expected=16421.2us
(kms_flip:7572) DEBUG: expected 8182, counted 144, encoder type 2
(kms_flip:7572) DEBUG: dropped frames, expected 8182, counted 144, encoder type 2
(kms_flip:7572) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7572) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7572) igt_core-INFO: Stack trace:
(kms_flip:7572) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7572) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7572) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7572) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7572) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7572) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7572) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7572) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AD-DP2-HDMI-A3: FAIL (7.478s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.710s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.680s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.664s)
Subtest 2x-plain-flip-ts-check: FAIL (30.312s)