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

shard-bmg-7

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

Using IGT_SRANDOM=1739409791 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 17254.2us +- 5.916us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 17254us +- 5.916us, difference 587.6us (99.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 AB-DP2-HDMI-A3: FAIL (7.098s)
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 16902.7us +- 7.199us accuracy 0.13%
vblank interval differs from modeline! expected 16666.7us, measured 16903us +- 7.199us, difference 236.0us (32.8 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 (8.752s)
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 16744.1us +- 3.255us accuracy 0.06%
vblank interval differs from modeline! expected 16666.7us, measured 16744us +- 3.255us, difference 77.4us (23.8 sigma)
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.656s)
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 16708.6us +- 4.082us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 16709us +- 4.082us, difference 41.9us (10.3 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.672s)
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 16686.0us +- 6.033us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16686us +- 6.033us, difference 19.3us (3.2 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.645s)
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 16682.8us +- 5.745us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16683us +- 5.745us, difference 16.1us (2.8 sigma)
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.649s)
Subtest 2x-plain-flip-ts-check: FAIL (38.532s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:7580) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7580) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7580) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7580) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:7580) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7580) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7580) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:7580) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7580) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9924c10, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9924c10, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9933170, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9933170, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9969d80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9969d80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9977c20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) intel_allocator_simple-DEBUG: <ial: 0x5dd4d9977c20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7580) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7580) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
(kms_flip:7580) DEBUG: No stale events found
(kms_flip:7580) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7580) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7580) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7580) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7580) INFO: Expected frametime: 16667us; measured 17254.2us +- 5.916us accuracy 0.10%
(kms_flip:7580) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17254us +- 5.916us, difference 587.6us (99.3 sigma)
(kms_flip:7580) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 279.601318
current_received_ts = 279.600922
current_seq = 11818
count = 0
seq_step = 1
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.601318
last_received_ts = 279.600922
last_seq = 11818
current_ts = 279.618591
current_received_ts = 279.618225
current_seq = 11819
count = 1
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.601318/11818, current 279.618591/11819: elapsed=17264.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.618591
last_received_ts = 279.618225
last_seq = 11819
current_ts = 279.635834
current_received_ts = 279.635223
current_seq = 11820
count = 2
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.618591/11819, current 279.635834/11820: elapsed=17240.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.635834
last_received_ts = 279.635223
last_seq = 11820
current_ts = 279.653107
current_received_ts = 279.652679
current_seq = 11821
count = 3
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.635834/11820, current 279.653107/11821: elapsed=17267.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.653107
last_received_ts = 279.652679
last_seq = 11821
current_ts = 279.670349
current_received_ts = 279.669922
current_seq = 11822
count = 4
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.653107/11821, current 279.670349/11822: elapsed=17246.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.670349
last_received_ts = 279.669922
last_seq = 11822
current_ts = 279.687592
current_received_ts = 279.687134
current_seq = 11823
count = 5
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.670349/11822, current 279.687592/11823: elapsed=17248.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.687592
last_received_ts = 279.687134
last_seq = 11823
current_ts = 279.704865
current_received_ts = 279.704376
current_seq = 11824
count = 6
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.687592/11823, current 279.704865/11824: elapsed=17255.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.704865
last_received_ts = 279.704376
last_seq = 11824
current_ts = 279.722107
current_received_ts = 279.721619
current_seq = 11825
count = 7
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.704865/11824, current 279.722107/11825: elapsed=17264.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.722107
last_received_ts = 279.721619
last_seq = 11825
current_ts = 279.739380
current_received_ts = 279.738861
current_seq = 11826
count = 8
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.722107/11825, current 279.739380/11826: elapsed=17252.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.739380
last_received_ts = 279.738861
last_seq = 11826
current_ts = 279.756622
current_received_ts = 279.756073
current_seq = 11827
count = 9
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.739380/11826, current 279.756622/11827: elapsed=17252.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.756622
last_received_ts = 279.756073
last_seq = 11827
current_ts = 279.773865
current_received_ts = 279.773376
current_seq = 11828
count = 10
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.756622/11827, current 279.773865/11828: elapsed=17249.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.773865
last_received_ts = 279.773376
last_seq = 11828
current_ts = 279.791107
current_received_ts = 279.790588
current_seq = 11829
count = 11
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.773865/11828, current 279.791107/11829: elapsed=17255.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.791107
last_received_ts = 279.790588
last_seq = 11829
current_ts = 279.808380
current_received_ts = 279.807892
current_seq = 11830
count = 12
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.791107/11829, current 279.808380/11830: elapsed=17249.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.808380
last_received_ts = 279.807892
last_seq = 11830
current_ts = 279.825623
current_received_ts = 279.825104
current_seq = 11831
count = 13
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.808380/11830, current 279.825623/11831: elapsed=17263.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.825623
last_received_ts = 279.825104
last_seq = 11831
current_ts = 279.842896
current_received_ts = 279.842407
current_seq = 11832
count = 14
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.825623/11831, current 279.842896/11832: elapsed=17253.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.842896
last_received_ts = 279.842407
last_seq = 11832
current_ts = 279.860138
current_received_ts = 279.859650
current_seq = 11833
count = 15
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.842896/11832, current 279.860138/11833: elapsed=17242.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.860138
last_received_ts = 279.859650
last_seq = 11833
current_ts = 279.877380
current_received_ts = 279.876892
current_seq = 11834
count = 16
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.860138/11833, current 279.877380/11834: elapsed=17263.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.877380
last_received_ts = 279.876892
last_seq = 11834
current_ts = 279.894623
current_received_ts = 279.894135
current_seq = 11835
count = 17
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.877380/11834, current 279.894623/11835: elapsed=17246.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.894623
last_received_ts = 279.894135
last_seq = 11835
current_ts = 279.911896
current_received_ts = 279.911407
current_seq = 11836
count = 18
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.894623/11835, current 279.911896/11836: elapsed=17259.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.911896
last_received_ts = 279.911407
last_seq = 11836
current_ts = 279.929138
current_received_ts = 279.928619
current_seq = 11837
count = 19
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.911896/11836, current 279.929138/11837: elapsed=17251.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.929138
last_received_ts = 279.928619
last_seq = 11837
current_ts = 279.946411
current_received_ts = 279.945892
current_seq = 11838
count = 20
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.929138/11837, current 279.946411/11838: elapsed=17261.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.946411
last_received_ts = 279.945892
last_seq = 11838
current_ts = 279.963654
current_received_ts = 279.963165
current_seq = 11839
count = 21
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.946411/11838, current 279.963654/11839: elapsed=17254.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.963654
last_received_ts = 279.963165
last_seq = 11839
current_ts = 279.980896
current_received_ts = 279.980377
current_seq = 11840
count = 22
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.963654/11839, current 279.980896/11840: elapsed=17243.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.980896
last_received_ts = 279.980377
last_seq = 11840
current_ts = 279.998169
current_received_ts = 279.997711
current_seq = 11841
count = 23
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.980896/11840, current 279.998169/11841: elapsed=17259.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 279.998169
last_received_ts = 279.997711
last_seq = 11841
current_ts = 280.015411
current_received_ts = 280.014954
current_seq = 11842
count = 24
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 279.998169/11841, current 280.015411/11842: elapsed=17257.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.015411
last_received_ts = 280.014954
last_seq = 11842
current_ts = 280.032684
current_received_ts = 280.032135
current_seq = 11843
count = 25
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.015411/11842, current 280.032684/11843: elapsed=17251.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.032684
last_received_ts = 280.032135
last_seq = 11843
current_ts = 280.049927
current_received_ts = 280.049408
current_seq = 11844
count = 26
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.032684/11843, current 280.049927/11844: elapsed=17249.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.049927
last_received_ts = 280.049408
last_seq = 11844
current_ts = 280.067169
current_received_ts = 280.066650
current_seq = 11845
count = 27
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.049927/11844, current 280.067169/11845: elapsed=17258.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.067169
last_received_ts = 280.066650
last_seq = 11845
current_ts = 280.084412
current_received_ts = 280.083923
current_seq = 11846
count = 28
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.067169/11845, current 280.084412/11846: elapsed=17246.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.084412
last_received_ts = 280.083923
last_seq = 11846
current_ts = 280.101685
current_received_ts = 280.101196
current_seq = 11847
count = 29
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.084412/11846, current 280.101685/11847: elapsed=17251.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.101685
last_received_ts = 280.101196
last_seq = 11847
current_ts = 280.118927
current_received_ts = 280.118408
current_seq = 11848
count = 30
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.101685/11847, current 280.118927/11848: elapsed=17263.0us expected=17254.2us +- 86.3us, error 0.1%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.118927
last_received_ts = 280.118408
last_seq = 11848
current_ts = 280.136200
current_received_ts = 280.135712
current_seq = 11849
count = 31
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.118927/11848, current 280.136200/11849: elapsed=17250.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.136200
last_received_ts = 280.135712
last_seq = 11849
current_ts = 280.153442
current_received_ts = 280.153015
current_seq = 11850
count = 32
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.136200/11849, current 280.153442/11850: elapsed=17252.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.153442
last_received_ts = 280.153015
last_seq = 11850
current_ts = 280.170685
current_received_ts = 280.170258
current_seq = 11851
count = 33
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.153442/11850, current 280.170685/11851: elapsed=17255.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.170685
last_received_ts = 280.170258
last_seq = 11851
current_ts = 280.187958
current_received_ts = 280.187469
current_seq = 11852
count = 34
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.170685/11851, current 280.187958/11852: elapsed=17246.0us expected=17254.2us +- 86.3us, error 0.0%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.187958
last_received_ts = 280.187469
last_seq = 11852
current_ts = 280.205139
current_received_ts = 280.204620
current_seq = 11853
count = 35
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.187958/11852, current 280.205139/11853: elapsed=17182.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.205139
last_received_ts = 280.204620
last_seq = 11853
current_ts = 280.222321
current_received_ts = 280.221863
current_seq = 11854
count = 36
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.205139/11853, current 280.222321/11854: elapsed=17193.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.222321
last_received_ts = 280.221863
last_seq = 11854
current_ts = 280.239502
current_received_ts = 280.239075
current_seq = 11855
count = 37
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.222321/11854, current 280.239502/11855: elapsed=17183.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.239502
last_received_ts = 280.239075
last_seq = 11855
current_ts = 280.256683
current_received_ts = 280.256165
current_seq = 11856
count = 38
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.239502/11855, current 280.256683/11856: elapsed=17175.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.256683
last_received_ts = 280.256165
last_seq = 11856
current_ts = 280.273865
current_received_ts = 280.273376
current_seq = 11857
count = 39
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.256683/11856, current 280.273865/11857: elapsed=17183.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.273865
last_received_ts = 280.273376
last_seq = 11857
current_ts = 280.291046
current_received_ts = 280.290527
current_seq = 11858
count = 40
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.273865/11857, current 280.291046/11858: elapsed=17173.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.291046
last_received_ts = 280.290527
last_seq = 11858
current_ts = 280.308228
current_received_ts = 280.307739
current_seq = 11859
count = 41
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.291046/11858, current 280.308228/11859: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.308228
last_received_ts = 280.307739
last_seq = 11859
current_ts = 280.325409
current_received_ts = 280.324890
current_seq = 11860
count = 42
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.308228/11859, current 280.325409/11860: elapsed=17185.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.325409
last_received_ts = 280.324890
last_seq = 11860
current_ts = 280.342560
current_received_ts = 280.342072
current_seq = 11861
count = 43
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.325409/11860, current 280.342560/11861: elapsed=17171.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.342560
last_received_ts = 280.342072
last_seq = 11861
current_ts = 280.359741
current_received_ts = 280.359253
current_seq = 11862
count = 44
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.342560/11861, current 280.359741/11862: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.359741
last_received_ts = 280.359253
last_seq = 11862
current_ts = 280.376953
current_received_ts = 280.376434
current_seq = 11863
count = 45
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.359741/11862, current 280.376953/11863: elapsed=17192.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.376953
last_received_ts = 280.376434
last_seq = 11863
current_ts = 280.394135
current_received_ts = 280.393646
current_seq = 11864
count = 46
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.376953/11863, current 280.394135/11864: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.394135
last_received_ts = 280.393646
last_seq = 11864
current_ts = 280.411316
current_received_ts = 280.410828
current_seq = 11865
count = 47
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.394135/11864, current 280.411316/11865: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.411316
last_received_ts = 280.410828
last_seq = 11865
current_ts = 280.428467
current_received_ts = 280.427979
current_seq = 11866
count = 48
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.411316/11865, current 280.428467/11866: elapsed=17172.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.428467
last_received_ts = 280.427979
last_seq = 11866
current_ts = 280.445648
current_received_ts = 280.445160
current_seq = 11867
count = 49
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.428467/11866, current 280.445648/11867: elapsed=17180.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.445648
last_received_ts = 280.445160
last_seq = 11867
current_ts = 280.462860
current_received_ts = 280.462341
current_seq = 11868
count = 50
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.445648/11867, current 280.462860/11868: elapsed=17191.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.462860
last_received_ts = 280.462341
last_seq = 11868
current_ts = 280.480011
current_received_ts = 280.479553
current_seq = 11869
count = 51
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.462860/11868, current 280.480011/11869: elapsed=17171.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.480011
last_received_ts = 280.479553
last_seq = 11869
current_ts = 280.497223
current_received_ts = 280.496826
current_seq = 11870
count = 52
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.480011/11869, current 280.497223/11870: elapsed=17187.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.497223
last_received_ts = 280.496826
last_seq = 11870
current_ts = 280.514404
current_received_ts = 280.513885
current_seq = 11871
count = 53
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.497223/11870, current 280.514404/11871: elapsed=17187.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.514404
last_received_ts = 280.513885
last_seq = 11871
current_ts = 280.531586
current_received_ts = 280.531158
current_seq = 11872
count = 54
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.514404/11871, current 280.531586/11872: elapsed=17181.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.531586
last_received_ts = 280.531158
last_seq = 11872
current_ts = 280.548767
current_received_ts = 280.548309
current_seq = 11873
count = 55
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.531586/11872, current 280.548767/11873: elapsed=17178.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.548767
last_received_ts = 280.548309
last_seq = 11873
current_ts = 280.565918
current_received_ts = 280.565308
current_seq = 11874
count = 56
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.548767/11873, current 280.565918/11874: elapsed=17172.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.565918
last_received_ts = 280.565308
last_seq = 11874
current_ts = 280.583130
current_received_ts = 280.582703
current_seq = 11875
count = 57
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.565918/11874, current 280.583130/11875: elapsed=17196.0us expected=17254.2us +- 86.3us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.583130
last_received_ts = 280.582703
last_seq = 11875
current_ts = 280.600311
current_received_ts = 280.599884
current_seq = 11876
count = 58
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.583130/11875, current 280.600311/11876: elapsed=17178.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.600311
last_received_ts = 280.599884
last_seq = 11876
current_ts = 280.617493
current_received_ts = 280.617096
current_seq = 11877
count = 59
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.600311/11876, current 280.617493/11877: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.617493
last_received_ts = 280.617096
last_seq = 11877
current_ts = 280.634674
current_received_ts = 280.634277
current_seq = 11878
count = 60
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.617493/11877, current 280.634674/11878: elapsed=17188.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.634674
last_received_ts = 280.634277
last_seq = 11878
current_ts = 280.651855
current_received_ts = 280.651459
current_seq = 11879
count = 61
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.634674/11878, current 280.651855/11879: elapsed=17176.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.651855
last_received_ts = 280.651459
last_seq = 11879
current_ts = 280.669037
current_received_ts = 280.668610
current_seq = 11880
count = 62
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.651855/11879, current 280.669037/11880: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.669037
last_received_ts = 280.668610
last_seq = 11880
current_ts = 280.686218
current_received_ts = 280.685760
current_seq = 11881
count = 63
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.669037/11880, current 280.686218/11881: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.686218
last_received_ts = 280.685760
last_seq = 11881
current_ts = 280.703369
current_received_ts = 280.702972
current_seq = 11882
count = 64
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.686218/11881, current 280.703369/11882: elapsed=17172.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.703369
last_received_ts = 280.702972
last_seq = 11882
current_ts = 280.720581
current_received_ts = 280.720184
current_seq = 11883
count = 65
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.703369/11882, current 280.720581/11883: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.720581
last_received_ts = 280.720184
last_seq = 11883
current_ts = 280.737732
current_received_ts = 280.737366
current_seq = 11884
count = 66
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.720581/11883, current 280.737732/11884: elapsed=17176.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.737732
last_received_ts = 280.737366
last_seq = 11884
current_ts = 280.754944
current_received_ts = 280.754486
current_seq = 11885
count = 67
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.737732/11884, current 280.754944/11885: elapsed=17187.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.754944
last_received_ts = 280.754486
last_seq = 11885
current_ts = 280.772125
current_received_ts = 280.771790
current_seq = 11886
count = 68
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.754944/11885, current 280.772125/11886: elapsed=17181.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.772125
last_received_ts = 280.771790
last_seq = 11886
current_ts = 280.789307
current_received_ts = 280.788849
current_seq = 11887
count = 69
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.772125/11886, current 280.789307/11887: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.789307
last_received_ts = 280.788849
last_seq = 11887
current_ts = 280.806458
current_received_ts = 280.806061
current_seq = 11888
count = 70
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.789307/11887, current 280.806458/11888: elapsed=17170.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.806458
last_received_ts = 280.806061
last_seq = 11888
current_ts = 280.823639
current_received_ts = 280.823242
current_seq = 11889
count = 71
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.806458/11888, current 280.823639/11889: elapsed=17184.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.823639
last_received_ts = 280.823242
last_seq = 11889
current_ts = 280.840820
current_received_ts = 280.840210
current_seq = 11890
count = 72
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.823639/11889, current 280.840820/11890: elapsed=17175.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.840820
last_received_ts = 280.840210
last_seq = 11890
current_ts = 280.858032
current_received_ts = 280.857422
current_seq = 11891
count = 73
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.840820/11890, current 280.858032/11891: elapsed=17189.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.858032
last_received_ts = 280.857422
last_seq = 11891
current_ts = 280.875214
current_received_ts = 280.874817
current_seq = 11892
count = 74
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.858032/11891, current 280.875214/11892: elapsed=17187.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.875214
last_received_ts = 280.874817
last_seq = 11892
current_ts = 280.892365
current_received_ts = 280.891998
current_seq = 11893
count = 75
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.875214/11892, current 280.892365/11893: elapsed=17174.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.892365
last_received_ts = 280.891998
last_seq = 11893
current_ts = 280.909576
current_received_ts = 280.909119
current_seq = 11894
count = 76
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.892365/11893, current 280.909576/11894: elapsed=17189.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.909576
last_received_ts = 280.909119
last_seq = 11894
current_ts = 280.926758
current_received_ts = 280.926361
current_seq = 11895
count = 77
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.909576/11894, current 280.926758/11895: elapsed=17181.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.926758
last_received_ts = 280.926361
last_seq = 11895
current_ts = 280.943939
current_received_ts = 280.943512
current_seq = 11896
count = 78
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.926758/11895, current 280.943939/11896: elapsed=17180.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.943939
last_received_ts = 280.943512
last_seq = 11896
current_ts = 280.961121
current_received_ts = 280.960754
current_seq = 11897
count = 79
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.943939/11896, current 280.961121/11897: elapsed=17185.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.961121
last_received_ts = 280.960754
last_seq = 11897
current_ts = 280.978302
current_received_ts = 280.977844
current_seq = 11898
count = 80
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.961121/11897, current 280.978302/11898: elapsed=17178.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.978302
last_received_ts = 280.977844
last_seq = 11898
current_ts = 280.995453
current_received_ts = 280.994965
current_seq = 11899
count = 81
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.978302/11898, current 280.995453/11899: elapsed=17170.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 280.995453
last_received_ts = 280.994965
last_seq = 11899
current_ts = 281.012634
current_received_ts = 281.012115
current_seq = 11900
count = 82
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 280.995453/11899, current 281.012634/11900: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.012634
last_received_ts = 281.012115
last_seq = 11900
current_ts = 281.029816
current_received_ts = 281.029297
current_seq = 11901
count = 83
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.012634/11900, current 281.029816/11901: elapsed=17189.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.029816
last_received_ts = 281.029297
last_seq = 11901
current_ts = 281.046997
current_received_ts = 281.046509
current_seq = 11902
count = 84
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.029816/11901, current 281.046997/11902: elapsed=17180.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.046997
last_received_ts = 281.046509
last_seq = 11902
current_ts = 281.064178
current_received_ts = 281.063690
current_seq = 11903
count = 85
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.046997/11902, current 281.064178/11903: elapsed=17179.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.064178
last_received_ts = 281.063690
last_seq = 11903
current_ts = 281.081360
current_received_ts = 281.080933
current_seq = 11904
count = 86
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.064178/11903, current 281.081360/11904: elapsed=17182.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.081360
last_received_ts = 281.080933
last_seq = 11904
current_ts = 281.098541
current_received_ts = 281.098022
current_seq = 11905
count = 87
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.081360/11904, current 281.098541/11905: elapsed=17185.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.098541
last_received_ts = 281.098022
last_seq = 11905
current_ts = 281.115723
current_received_ts = 281.115204
current_seq = 11906
count = 88
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.098541/11905, current 281.115723/11906: elapsed=17174.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.115723
last_received_ts = 281.115204
last_seq = 11906
current_ts = 281.132904
current_received_ts = 281.132477
current_seq = 11907
count = 89
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.115723/11906, current 281.132904/11907: elapsed=17190.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.132904
last_received_ts = 281.132477
last_seq = 11907
current_ts = 281.150116
current_received_ts = 281.149658
current_seq = 11908
count = 90
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.132904/11907, current 281.150116/11908: elapsed=17186.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.150116
last_received_ts = 281.149658
last_seq = 11908
current_ts = 281.167267
current_received_ts = 281.166748
current_seq = 11909
count = 91
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.150116/11908, current 281.167267/11909: elapsed=17169.0us expected=17254.2us +- 86.3us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.167267
last_received_ts = 281.166748
last_seq = 11909
current_ts = 281.184479
current_received_ts = 281.183960
current_seq = 11910
count = 92
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.167267/11909, current 281.184479/11910: elapsed=17192.0us expected=17254.2us +- 86.3us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 281.184479
last_received_ts = 281.183960
last_seq = 11910
current_ts = 281.201599
current_received_ts = 281.201080
current_seq = 11911
count = 93
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 281.184479/11910, current 281.201599/11911: elapsed=17121.0us expected=17254.2us +- 86.3us, error 0.8%
(kms_flip:7580) DEBUG: inconsistent flip ts/seq: last 281.184479/11910, current 281.201599/11911: elapsed=17121.0us expected=17254.2us
(kms_flip:7580) DEBUG: expected 0, counted 93, encoder type 2
(kms_flip:7580) DEBUG: dropped frames, expected 0, counted 93, encoder type 2
(kms_flip:7580) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7580) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7580) igt_core-INFO: Stack trace:
(kms_flip:7580) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7580) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7580) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7580) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7580) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7580) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7580) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7580) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (7.098s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:7580) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7580) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7580) DEBUG: flip ts/seq: last 288.161896/12316, current 288.178772/12317: elapsed=16875.0us expected=16902.7us +- 84.5us, error 0.2%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.178772
last_received_ts = 288.178192
last_seq = 12317
current_ts = 288.195648
current_received_ts = 288.195068
current_seq = 12318
count = 80
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.178772/12317, current 288.195648/12318: elapsed=16861.0us expected=16902.7us +- 84.5us, error 0.2%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.195648
last_received_ts = 288.195068
last_seq = 12318
current_ts = 288.212494
current_received_ts = 288.211884
current_seq = 12319
count = 81
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.195648/12318, current 288.212494/12319: elapsed=16852.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.212494
last_received_ts = 288.211884
last_seq = 12319
current_ts = 288.229340
current_received_ts = 288.228790
current_seq = 12320
count = 82
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.212494/12319, current 288.229340/12320: elapsed=16859.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.229340
last_received_ts = 288.228790
last_seq = 12320
current_ts = 288.246185
current_received_ts = 288.245728
current_seq = 12321
count = 83
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.229340/12320, current 288.246185/12321: elapsed=16836.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.246185
last_received_ts = 288.245728
last_seq = 12321
current_ts = 288.263062
current_received_ts = 288.262543
current_seq = 12322
count = 84
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.246185/12321, current 288.263062/12322: elapsed=16862.0us expected=16902.7us +- 84.5us, error 0.2%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.263062
last_received_ts = 288.262543
last_seq = 12322
current_ts = 288.279877
current_received_ts = 288.279419
current_seq = 12323
count = 85
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.263062/12322, current 288.279877/12323: elapsed=16838.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.279877
last_received_ts = 288.279419
last_seq = 12323
current_ts = 288.296753
current_received_ts = 288.296204
current_seq = 12324
count = 86
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.279877/12323, current 288.296753/12324: elapsed=16859.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.296753
last_received_ts = 288.296204
last_seq = 12324
current_ts = 288.313599
current_received_ts = 288.312988
current_seq = 12325
count = 87
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.296753/12324, current 288.313599/12325: elapsed=16844.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.313599
last_received_ts = 288.312988
last_seq = 12325
current_ts = 288.330444
current_received_ts = 288.329834
current_seq = 12326
count = 88
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.313599/12325, current 288.330444/12326: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.330444
last_received_ts = 288.329834
last_seq = 12326
current_ts = 288.347290
current_received_ts = 288.346680
current_seq = 12327
count = 89
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.330444/12326, current 288.347290/12327: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.347290
last_received_ts = 288.346680
last_seq = 12327
current_ts = 288.364136
current_received_ts = 288.363525
current_seq = 12328
count = 90
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.347290/12327, current 288.364136/12328: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.364136
last_received_ts = 288.363525
last_seq = 12328
current_ts = 288.380981
current_received_ts = 288.380371
current_seq = 12329
count = 91
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.364136/12328, current 288.380981/12329: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.380981
last_received_ts = 288.380371
last_seq = 12329
current_ts = 288.397827
current_received_ts = 288.397217
current_seq = 12330
count = 92
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.380981/12329, current 288.397827/12330: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.397827
last_received_ts = 288.397217
last_seq = 12330
current_ts = 288.414703
current_received_ts = 288.414093
current_seq = 12331
count = 93
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.397827/12330, current 288.414703/12331: elapsed=16853.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.414703
last_received_ts = 288.414093
last_seq = 12331
current_ts = 288.431549
current_received_ts = 288.430939
current_seq = 12332
count = 94
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.414703/12331, current 288.431549/12332: elapsed=16846.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.431549
last_received_ts = 288.430939
last_seq = 12332
current_ts = 288.448395
current_received_ts = 288.447784
current_seq = 12333
count = 95
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.431549/12332, current 288.448395/12333: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.448395
last_received_ts = 288.447784
last_seq = 12333
current_ts = 288.465240
current_received_ts = 288.464630
current_seq = 12334
count = 96
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.448395/12333, current 288.465240/12334: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.465240
last_received_ts = 288.464630
last_seq = 12334
current_ts = 288.482086
current_received_ts = 288.481476
current_seq = 12335
count = 97
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.465240/12334, current 288.482086/12335: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.482086
last_received_ts = 288.481476
last_seq = 12335
current_ts = 288.498932
current_received_ts = 288.498352
current_seq = 12336
count = 98
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.482086/12335, current 288.498932/12336: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.498932
last_received_ts = 288.498352
last_seq = 12336
current_ts = 288.515778
current_received_ts = 288.515167
current_seq = 12337
count = 99
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.498932/12336, current 288.515778/12337: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.515778
last_received_ts = 288.515167
last_seq = 12337
current_ts = 288.532623
current_received_ts = 288.532043
current_seq = 12338
count = 100
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.515778/12337, current 288.532623/12338: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.532623
last_received_ts = 288.532043
last_seq = 12338
current_ts = 288.549469
current_received_ts = 288.548889
current_seq = 12339
count = 101
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.532623/12338, current 288.549469/12339: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.549469
last_received_ts = 288.548889
last_seq = 12339
current_ts = 288.566345
current_received_ts = 288.565735
current_seq = 12340
count = 102
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.549469/12339, current 288.566345/12340: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.566345
last_received_ts = 288.565735
last_seq = 12340
current_ts = 288.583191
current_received_ts = 288.582581
current_seq = 12341
count = 103
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.566345/12340, current 288.583191/12341: elapsed=16848.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.583191
last_received_ts = 288.582581
last_seq = 12341
current_ts = 288.600037
current_received_ts = 288.599426
current_seq = 12342
count = 104
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.583191/12341, current 288.600037/12342: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.600037
last_received_ts = 288.599426
last_seq = 12342
current_ts = 288.616882
current_received_ts = 288.616272
current_seq = 12343
count = 105
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.600037/12342, current 288.616882/12343: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.616882
last_received_ts = 288.616272
last_seq = 12343
current_ts = 288.633728
current_received_ts = 288.633118
current_seq = 12344
count = 106
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.616882/12343, current 288.633728/12344: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.633728
last_received_ts = 288.633118
last_seq = 12344
current_ts = 288.650574
current_received_ts = 288.649994
current_seq = 12345
count = 107
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.633728/12344, current 288.650574/12345: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.650574
last_received_ts = 288.649994
last_seq = 12345
current_ts = 288.667419
current_received_ts = 288.666840
current_seq = 12346
count = 108
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.650574/12345, current 288.667419/12346: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.667419
last_received_ts = 288.666840
last_seq = 12346
current_ts = 288.684265
current_received_ts = 288.683685
current_seq = 12347
count = 109
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.667419/12346, current 288.684265/12347: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.684265
last_received_ts = 288.683685
last_seq = 12347
current_ts = 288.701141
current_received_ts = 288.700531
current_seq = 12348
count = 110
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.684265/12347, current 288.701141/12348: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.701141
last_received_ts = 288.700531
last_seq = 12348
current_ts = 288.717987
current_received_ts = 288.717377
current_seq = 12349
count = 111
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.701141/12348, current 288.717987/12349: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.717987
last_received_ts = 288.717377
last_seq = 12349
current_ts = 288.734833
current_received_ts = 288.734222
current_seq = 12350
count = 112
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.717987/12349, current 288.734833/12350: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.734833
last_received_ts = 288.734222
last_seq = 12350
current_ts = 288.751678
current_received_ts = 288.751099
current_seq = 12351
count = 113
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.734833/12350, current 288.751678/12351: elapsed=16852.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.751678
last_received_ts = 288.751099
last_seq = 12351
current_ts = 288.768524
current_received_ts = 288.767914
current_seq = 12352
count = 114
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.751678/12351, current 288.768524/12352: elapsed=16846.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.768524
last_received_ts = 288.767914
last_seq = 12352
current_ts = 288.785370
current_received_ts = 288.784760
current_seq = 12353
count = 115
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.768524/12352, current 288.785370/12353: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.785370
last_received_ts = 288.784760
last_seq = 12353
current_ts = 288.802216
current_received_ts = 288.801636
current_seq = 12354
count = 116
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.785370/12353, current 288.802216/12354: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.802216
last_received_ts = 288.801636
last_seq = 12354
current_ts = 288.819061
current_received_ts = 288.818481
current_seq = 12355
count = 117
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.802216/12354, current 288.819061/12355: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.819061
last_received_ts = 288.818481
last_seq = 12355
current_ts = 288.835938
current_received_ts = 288.835358
current_seq = 12356
count = 118
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.819061/12355, current 288.835938/12356: elapsed=16854.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.835938
last_received_ts = 288.835358
last_seq = 12356
current_ts = 288.852783
current_received_ts = 288.852203
current_seq = 12357
count = 119
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.835938/12356, current 288.852783/12357: elapsed=16840.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.852783
last_received_ts = 288.852203
last_seq = 12357
current_ts = 288.869629
current_received_ts = 288.869110
current_seq = 12358
count = 120
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.852783/12357, current 288.869629/12358: elapsed=16853.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.869629
last_received_ts = 288.869110
last_seq = 12358
current_ts = 288.886475
current_received_ts = 288.885895
current_seq = 12359
count = 121
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.869629/12358, current 288.886475/12359: elapsed=16845.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.886475
last_received_ts = 288.885895
last_seq = 12359
current_ts = 288.903320
current_received_ts = 288.902679
current_seq = 12360
count = 122
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.886475/12359, current 288.903320/12360: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.903320
last_received_ts = 288.902679
last_seq = 12360
current_ts = 288.920166
current_received_ts = 288.919556
current_seq = 12361
count = 123
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.903320/12360, current 288.920166/12361: elapsed=16853.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.920166
last_received_ts = 288.919556
last_seq = 12361
current_ts = 288.937012
current_received_ts = 288.936432
current_seq = 12362
count = 124
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.920166/12361, current 288.937012/12362: elapsed=16851.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.937012
last_received_ts = 288.936432
last_seq = 12362
current_ts = 288.953857
current_received_ts = 288.953278
current_seq = 12363
count = 125
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.937012/12362, current 288.953857/12363: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.953857
last_received_ts = 288.953278
last_seq = 12363
current_ts = 288.970734
current_received_ts = 288.970123
current_seq = 12364
count = 126
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.953857/12363, current 288.970734/12364: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.970734
last_received_ts = 288.970123
last_seq = 12364
current_ts = 288.987579
current_received_ts = 288.986969
current_seq = 12365
count = 127
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.970734/12364, current 288.987579/12365: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 288.987579
last_received_ts = 288.986969
last_seq = 12365
current_ts = 289.004425
current_received_ts = 289.003815
current_seq = 12366
count = 128
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 288.987579/12365, current 289.004425/12366: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.004425
last_received_ts = 289.003815
last_seq = 12366
current_ts = 289.021271
current_received_ts = 289.020660
current_seq = 12367
count = 129
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.004425/12366, current 289.021271/12367: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.021271
last_received_ts = 289.020660
last_seq = 12367
current_ts = 289.038116
current_received_ts = 289.037506
current_seq = 12368
count = 130
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.021271/12367, current 289.038116/12368: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.038116
last_received_ts = 289.037506
last_seq = 12368
current_ts = 289.054962
current_received_ts = 289.054352
current_seq = 12369
count = 131
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.038116/12368, current 289.054962/12369: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.054962
last_received_ts = 289.054352
last_seq = 12369
current_ts = 289.071808
current_received_ts = 289.071198
current_seq = 12370
count = 132
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.054962/12369, current 289.071808/12370: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.071808
last_received_ts = 289.071198
last_seq = 12370
current_ts = 289.088654
current_received_ts = 289.088104
current_seq = 12371
count = 133
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.071808/12370, current 289.088654/12371: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.088654
last_received_ts = 289.088104
last_seq = 12371
current_ts = 289.105530
current_received_ts = 289.104919
current_seq = 12372
count = 134
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.088654/12371, current 289.105530/12372: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.105530
last_received_ts = 289.104919
last_seq = 12372
current_ts = 289.122375
current_received_ts = 289.121765
current_seq = 12373
count = 135
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.105530/12372, current 289.122375/12373: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.122375
last_received_ts = 289.121765
last_seq = 12373
current_ts = 289.139221
current_received_ts = 289.138611
current_seq = 12374
count = 136
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.122375/12373, current 289.139221/12374: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.139221
last_received_ts = 289.138611
last_seq = 12374
current_ts = 289.156067
current_received_ts = 289.155457
current_seq = 12375
count = 137
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.139221/12374, current 289.156067/12375: elapsed=16849.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.156067
last_received_ts = 289.155457
last_seq = 12375
current_ts = 289.172913
current_received_ts = 289.172302
current_seq = 12376
count = 138
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.156067/12375, current 289.172913/12376: elapsed=16850.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.172913
last_received_ts = 289.172302
last_seq = 12376
current_ts = 289.189758
current_received_ts = 289.189148
current_seq = 12377
count = 139
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.172913/12376, current 289.189758/12377: elapsed=16847.0us expected=16902.7us +- 84.5us, error 0.3%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.189758
last_received_ts = 289.189148
last_seq = 12377
current_ts = 289.206573
current_received_ts = 289.205994
current_seq = 12378
count = 140
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.189758/12377, current 289.206573/12378: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.206573
last_received_ts = 289.205994
last_seq = 12378
current_ts = 289.223419
current_received_ts = 289.222809
current_seq = 12379
count = 141
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.206573/12378, current 289.223419/12379: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.223419
last_received_ts = 289.222809
last_seq = 12379
current_ts = 289.240234
current_received_ts = 289.239624
current_seq = 12380
count = 142
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.223419/12379, current 289.240234/12380: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.240234
last_received_ts = 289.239624
last_seq = 12380
current_ts = 289.257080
current_received_ts = 289.256470
current_seq = 12381
count = 143
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.240234/12380, current 289.257080/12381: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.257080
last_received_ts = 289.256470
last_seq = 12381
current_ts = 289.273895
current_received_ts = 289.273285
current_seq = 12382
count = 144
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.257080/12381, current 289.273895/12382: elapsed=16826.0us expected=16902.7us +- 84.5us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.273895
last_received_ts = 289.273285
last_seq = 12382
current_ts = 289.290741
current_received_ts = 289.290131
current_seq = 12383
count = 145
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.273895/12382, current 289.290741/12383: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.290741
last_received_ts = 289.290131
last_seq = 12383
current_ts = 289.307556
current_received_ts = 289.306946
current_seq = 12384
count = 146
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.290741/12383, current 289.307556/12384: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.307556
last_received_ts = 289.306946
last_seq = 12384
current_ts = 289.324371
current_received_ts = 289.323761
current_seq = 12385
count = 147
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.307556/12384, current 289.324371/12385: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.324371
last_received_ts = 289.323761
last_seq = 12385
current_ts = 289.341217
current_received_ts = 289.340607
current_seq = 12386
count = 148
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.324371/12385, current 289.341217/12386: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.341217
last_received_ts = 289.340607
last_seq = 12386
current_ts = 289.358032
current_received_ts = 289.357422
current_seq = 12387
count = 149
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.341217/12386, current 289.358032/12387: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.358032
last_received_ts = 289.357422
last_seq = 12387
current_ts = 289.374878
current_received_ts = 289.374268
current_seq = 12388
count = 150
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.358032/12387, current 289.374878/12388: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.374878
last_received_ts = 289.374268
last_seq = 12388
current_ts = 289.391693
current_received_ts = 289.391083
current_seq = 12389
count = 151
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.374878/12388, current 289.391693/12389: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.391693
last_received_ts = 289.391083
last_seq = 12389
current_ts = 289.408508
current_received_ts = 289.407928
current_seq = 12390
count = 152
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.391693/12389, current 289.408508/12390: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.408508
last_received_ts = 289.407928
last_seq = 12390
current_ts = 289.425354
current_received_ts = 289.424744
current_seq = 12391
count = 153
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.408508/12390, current 289.425354/12391: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.425354
last_received_ts = 289.424744
last_seq = 12391
current_ts = 289.442169
current_received_ts = 289.441559
current_seq = 12392
count = 154
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.425354/12391, current 289.442169/12392: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.442169
last_received_ts = 289.441559
last_seq = 12392
current_ts = 289.459015
current_received_ts = 289.458405
current_seq = 12393
count = 155
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.442169/12392, current 289.459015/12393: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.459015
last_received_ts = 289.458405
last_seq = 12393
current_ts = 289.475830
current_received_ts = 289.475220
current_seq = 12394
count = 156
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.459015/12393, current 289.475830/12394: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.475830
last_received_ts = 289.475220
last_seq = 12394
current_ts = 289.492645
current_received_ts = 289.492096
current_seq = 12395
count = 157
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.475830/12394, current 289.492645/12395: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.492645
last_received_ts = 289.492096
last_seq = 12395
current_ts = 289.509491
current_received_ts = 289.508911
current_seq = 12396
count = 158
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.492645/12395, current 289.509491/12396: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.509491
last_received_ts = 289.508911
last_seq = 12396
current_ts = 289.526306
current_received_ts = 289.525726
current_seq = 12397
count = 159
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.509491/12396, current 289.526306/12397: elapsed=16826.0us expected=16902.7us +- 84.5us, error 0.5%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.526306
last_received_ts = 289.525726
last_seq = 12397
current_ts = 289.543152
current_received_ts = 289.542542
current_seq = 12398
count = 160
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.526306/12397, current 289.543152/12398: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.543152
last_received_ts = 289.542542
last_seq = 12398
current_ts = 289.559967
current_received_ts = 289.559357
current_seq = 12399
count = 161
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.543152/12398, current 289.559967/12399: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.559967
last_received_ts = 289.559357
last_seq = 12399
current_ts = 289.576813
current_received_ts = 289.576202
current_seq = 12400
count = 162
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.559967/12399, current 289.576813/12400: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.576813
last_received_ts = 289.576202
last_seq = 12400
current_ts = 289.593628
current_received_ts = 289.593048
current_seq = 12401
count = 163
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.576813/12400, current 289.593628/12401: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.593628
last_received_ts = 289.593048
last_seq = 12401
current_ts = 289.610443
current_received_ts = 289.609863
current_seq = 12402
count = 164
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.593628/12401, current 289.610443/12402: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.610443
last_received_ts = 289.609863
last_seq = 12402
current_ts = 289.627289
current_received_ts = 289.626678
current_seq = 12403
count = 165
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.610443/12402, current 289.627289/12403: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.627289
last_received_ts = 289.626678
last_seq = 12403
current_ts = 289.644104
current_received_ts = 289.643677
current_seq = 12404
count = 166
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.627289/12403, current 289.644104/12404: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.644104
last_received_ts = 289.643677
last_seq = 12404
current_ts = 289.660950
current_received_ts = 289.660339
current_seq = 12405
count = 167
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.644104/12404, current 289.660950/12405: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.660950
last_received_ts = 289.660339
last_seq = 12405
current_ts = 289.677765
current_received_ts = 289.677155
current_seq = 12406
count = 168
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.660950/12405, current 289.677765/12406: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.677765
last_received_ts = 289.677155
last_seq = 12406
current_ts = 289.694580
current_received_ts = 289.694000
current_seq = 12407
count = 169
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.677765/12406, current 289.694580/12407: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.694580
last_received_ts = 289.694000
last_seq = 12407
current_ts = 289.711426
current_received_ts = 289.710815
current_seq = 12408
count = 170
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.694580/12407, current 289.711426/12408: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.711426
last_received_ts = 289.710815
last_seq = 12408
current_ts = 289.728241
current_received_ts = 289.727631
current_seq = 12409
count = 171
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.711426/12408, current 289.728241/12409: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.728241
last_received_ts = 289.727631
last_seq = 12409
current_ts = 289.745087
current_received_ts = 289.744476
current_seq = 12410
count = 172
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.728241/12409, current 289.745087/12410: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.745087
last_received_ts = 289.744476
last_seq = 12410
current_ts = 289.761902
current_received_ts = 289.761292
current_seq = 12411
count = 173
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.745087/12410, current 289.761902/12411: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.761902
last_received_ts = 289.761292
last_seq = 12411
current_ts = 289.778717
current_received_ts = 289.778137
current_seq = 12412
count = 174
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.761902/12411, current 289.778717/12412: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.778717
last_received_ts = 289.778137
last_seq = 12412
current_ts = 289.795563
current_received_ts = 289.794952
current_seq = 12413
count = 175
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.778717/12412, current 289.795563/12413: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.795563
last_received_ts = 289.794952
last_seq = 12413
current_ts = 289.812378
current_received_ts = 289.811768
current_seq = 12414
count = 176
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.795563/12413, current 289.812378/12414: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.812378
last_received_ts = 289.811768
last_seq = 12414
current_ts = 289.829224
current_received_ts = 289.828613
current_seq = 12415
count = 177
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.812378/12414, current 289.829224/12415: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.829224
last_received_ts = 289.828613
last_seq = 12415
current_ts = 289.846039
current_received_ts = 289.845428
current_seq = 12416
count = 178
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.829224/12415, current 289.846039/12416: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.846039
last_received_ts = 289.845428
last_seq = 12416
current_ts = 289.862885
current_received_ts = 289.862274
current_seq = 12417
count = 179
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.846039/12416, current 289.862885/12417: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.862885
last_received_ts = 289.862274
last_seq = 12417
current_ts = 289.879700
current_received_ts = 289.879089
current_seq = 12418
count = 180
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.862885/12417, current 289.879700/12418: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.879700
last_received_ts = 289.879089
last_seq = 12418
current_ts = 289.896515
current_received_ts = 289.895935
current_seq = 12419
count = 181
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.879700/12418, current 289.896515/12419: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.896515
last_received_ts = 289.895935
last_seq = 12419
current_ts = 289.913361
current_received_ts = 289.912750
current_seq = 12420
count = 182
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.896515/12419, current 289.913361/12420: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.913361
last_received_ts = 289.912750
last_seq = 12420
current_ts = 289.930176
current_received_ts = 289.929565
current_seq = 12421
count = 183
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.913361/12420, current 289.930176/12421: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.930176
last_received_ts = 289.929565
last_seq = 12421
current_ts = 289.947021
current_received_ts = 289.946411
current_seq = 12422
count = 184
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.930176/12421, current 289.947021/12422: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.947021
last_received_ts = 289.946411
last_seq = 12422
current_ts = 289.963837
current_received_ts = 289.963226
current_seq = 12423
count = 185
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.947021/12422, current 289.963837/12423: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.963837
last_received_ts = 289.963226
last_seq = 12423
current_ts = 289.980652
current_received_ts = 289.980072
current_seq = 12424
count = 186
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.963837/12423, current 289.980652/12424: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.980652
last_received_ts = 289.980072
last_seq = 12424
current_ts = 289.997498
current_received_ts = 289.996887
current_seq = 12425
count = 187
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.980652/12424, current 289.997498/12425: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 289.997498
last_received_ts = 289.996887
last_seq = 12425
current_ts = 290.014313
current_received_ts = 290.013702
current_seq = 12426
count = 188
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 289.997498/12425, current 290.014313/12426: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.014313
last_received_ts = 290.013702
last_seq = 12426
current_ts = 290.031158
current_received_ts = 290.030548
current_seq = 12427
count = 189
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.014313/12426, current 290.031158/12427: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.031158
last_received_ts = 290.030548
last_seq = 12427
current_ts = 290.047974
current_received_ts = 290.047363
current_seq = 12428
count = 190
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.031158/12427, current 290.047974/12428: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.047974
last_received_ts = 290.047363
last_seq = 12428
current_ts = 290.064789
current_received_ts = 290.064209
current_seq = 12429
count = 191
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.047974/12428, current 290.064789/12429: elapsed=16829.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.064789
last_received_ts = 290.064209
last_seq = 12429
current_ts = 290.081635
current_received_ts = 290.081085
current_seq = 12430
count = 192
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.064789/12429, current 290.081635/12430: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.081635
last_received_ts = 290.081085
last_seq = 12430
current_ts = 290.098450
current_received_ts = 290.097870
current_seq = 12431
count = 193
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.081635/12430, current 290.098450/12431: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.098450
last_received_ts = 290.097870
last_seq = 12431
current_ts = 290.115295
current_received_ts = 290.114685
current_seq = 12432
count = 194
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.098450/12431, current 290.115295/12432: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.115295
last_received_ts = 290.114685
last_seq = 12432
current_ts = 290.132111
current_received_ts = 290.131500
current_seq = 12433
count = 195
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.115295/12432, current 290.132111/12433: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.132111
last_received_ts = 290.131500
last_seq = 12433
current_ts = 290.148956
current_received_ts = 290.148346
current_seq = 12434
count = 196
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.132111/12433, current 290.148956/12434: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.148956
last_received_ts = 290.148346
last_seq = 12434
current_ts = 290.165771
current_received_ts = 290.165161
current_seq = 12435
count = 197
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.148956/12434, current 290.165771/12435: elapsed=16827.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.165771
last_received_ts = 290.165161
last_seq = 12435
current_ts = 290.182587
current_received_ts = 290.182007
current_seq = 12436
count = 198
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.165771/12435, current 290.182587/12436: elapsed=16828.0us expected=16902.7us +- 84.5us, error 0.4%
(kms_flip:7580) DEBUG: name = flip
last_ts = 290.182587
last_received_ts = 290.182007
last_seq = 12436
current_ts = 290.199402
current_received_ts = 290.198822
current_seq = 12437
count = 199
seq_step = 1
(kms_flip:7580) DEBUG: flip ts/seq: last 290.182587/12436, current 290.199402/12437: elapsed=16815.0us expected=16902.7us +- 84.5us, error 0.5%
(kms_flip:7580) DEBUG: inconsistent flip ts/seq: last 290.182587/12436, current 290.199402/12437: elapsed=16815.0us expected=16902.7us
(kms_flip:7580) DEBUG: expected 0, counted 199, encoder type 2
(kms_flip:7580) DEBUG: dropped frames, expected 0, counted 199, encoder type 2
(kms_flip:7580) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7580) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7580) igt_core-INFO: Stack trace:
(kms_flip:7580) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7580) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7580) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7580) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7580) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7580) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7580) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7580) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (8.752s)
Starting dynamic subtest: AD-DP2-HDMI-A3
Dynamic subtest AD-DP2-HDMI-A3: SUCCESS (5.656s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.672s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.645s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.649s)
Subtest 2x-plain-flip-ts-check: FAIL (38.532s)