Results for igt@kms_flip@2x-plain-flip-fb-recreate

shard-dg2-432

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

Using IGT_SRANDOM=1741122601 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: 2x-plain-flip-fb-recreate
Starting dynamic subtest: AB-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17279.4us +- 4.049us accuracy 0.07%
vblank interval differs from modeline! expected 16666.7us, measured 17279us +- 4.049us, difference 612.8us (151.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest AB-HDMI-A2-DP2: FAIL (4.209s)
Starting dynamic subtest: AC-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17029.4us +- 5.390us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 17029us +- 5.390us, difference 362.7us (67.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest AC-HDMI-A2-DP2: FAIL (4.849s)
Starting dynamic subtest: AD-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16857.7us +- 5.582us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16858us +- 5.582us, difference 191.0us (34.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest AD-HDMI-A2-DP2: FAIL (7.152s)
Starting dynamic subtest: BC-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16746.6us +- 6.937us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16747us +- 6.937us, difference 80.0us (11.5 sigma)
Dynamic subtest BC-HDMI-A2-DP2: SUCCESS (5.629s)
Starting dynamic subtest: BD-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16707.8us +- 4.539us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16708us +- 4.539us, difference 41.1us (9.1 sigma)
Dynamic subtest BD-HDMI-A2-DP2: SUCCESS (5.637s)
Starting dynamic subtest: CD-HDMI-A2-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16681.9us +- 6.054us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16682us +- 6.054us, difference 15.2us (2.5 sigma)
Dynamic subtest CD-HDMI-A2-DP2: SUCCESS (5.645s)
Subtest 2x-plain-flip-fb-recreate: FAIL (33.177s)

Starting subtest: 2x-plain-flip-fb-recreate
Starting dynamic subtest: AB-HDMI-A2-DP2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AB-HDMI-A2-DP2 failed.
**** DEBUG ****
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3839) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3839) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492866f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492866f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294260, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294260, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294140, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294140, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294140, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x594449294140, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3839) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3839) DEBUG: No stale events found
(kms_flip:3839) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3839) INFO: Expected frametime: 16667us; measured 17279.4us +- 4.049us accuracy 0.07%
(kms_flip:3839) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17279us +- 4.049us, difference 612.8us (151.3 sigma)
(kms_flip:3839) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 268.618317
current_received_ts = 268.617859
current_seq = 3812
count = 0
seq_step = 1
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.618317
last_received_ts = 268.617859
last_seq = 3812
current_ts = 268.635590
current_received_ts = 268.634979
current_seq = 3813
count = 1
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.618317/3812, current 268.635590/3813: elapsed=17270.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.635590
last_received_ts = 268.634979
last_seq = 3813
current_ts = 268.652863
current_received_ts = 268.652252
current_seq = 3814
count = 2
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.635590/3813, current 268.652863/3814: elapsed=17280.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.652863
last_received_ts = 268.652252
last_seq = 3814
current_ts = 268.670166
current_received_ts = 268.669617
current_seq = 3815
count = 3
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.652863/3814, current 268.670166/3815: elapsed=17291.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.670166
last_received_ts = 268.669617
last_seq = 3815
current_ts = 268.687439
current_received_ts = 268.686890
current_seq = 3816
count = 4
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.670166/3815, current 268.687439/3816: elapsed=17272.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.687439
last_received_ts = 268.686890
last_seq = 3816
current_ts = 268.704712
current_received_ts = 268.704102
current_seq = 3817
count = 5
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.687439/3816, current 268.704712/3817: elapsed=17277.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.704712
last_received_ts = 268.704102
last_seq = 3817
current_ts = 268.722015
current_received_ts = 268.721436
current_seq = 3818
count = 6
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.704712/3817, current 268.722015/3818: elapsed=17293.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.722015
last_received_ts = 268.721436
last_seq = 3818
current_ts = 268.739258
current_received_ts = 268.738647
current_seq = 3819
count = 7
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.722015/3818, current 268.739258/3819: elapsed=17266.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.739258
last_received_ts = 268.738647
last_seq = 3819
current_ts = 268.756561
current_received_ts = 268.756134
current_seq = 3820
count = 8
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.739258/3819, current 268.756561/3820: elapsed=17293.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.756561
last_received_ts = 268.756134
last_seq = 3820
current_ts = 268.773834
current_received_ts = 268.773285
current_seq = 3821
count = 9
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.756561/3820, current 268.773834/3821: elapsed=17281.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.773834
last_received_ts = 268.773285
last_seq = 3821
current_ts = 268.791107
current_received_ts = 268.790588
current_seq = 3822
count = 10
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.773834/3821, current 268.791107/3822: elapsed=17276.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.791107
last_received_ts = 268.790588
last_seq = 3822
current_ts = 268.808411
current_received_ts = 268.807831
current_seq = 3823
count = 11
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.791107/3822, current 268.808411/3823: elapsed=17279.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.808411
last_received_ts = 268.807831
last_seq = 3823
current_ts = 268.825684
current_received_ts = 268.825073
current_seq = 3824
count = 12
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.808411/3823, current 268.825684/3824: elapsed=17275.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.825684
last_received_ts = 268.825073
last_seq = 3824
current_ts = 268.842957
current_received_ts = 268.842346
current_seq = 3825
count = 13
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.825684/3824, current 268.842957/3825: elapsed=17285.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.842957
last_received_ts = 268.842346
last_seq = 3825
current_ts = 268.860229
current_received_ts = 268.859680
current_seq = 3826
count = 14
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.842957/3825, current 268.860229/3826: elapsed=17284.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.860229
last_received_ts = 268.859680
last_seq = 3826
current_ts = 268.877502
current_received_ts = 268.876984
current_seq = 3827
count = 15
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.860229/3826, current 268.877502/3827: elapsed=17268.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.877502
last_received_ts = 268.876984
last_seq = 3827
current_ts = 268.894806
current_received_ts = 268.894257
current_seq = 3828
count = 16
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.877502/3827, current 268.894806/3828: elapsed=17292.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.894806
last_received_ts = 268.894257
last_seq = 3828
current_ts = 268.912079
current_received_ts = 268.911530
current_seq = 3829
count = 17
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.894806/3828, current 268.912079/3829: elapsed=17280.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.912079
last_received_ts = 268.911530
last_seq = 3829
current_ts = 268.929352
current_received_ts = 268.928802
current_seq = 3830
count = 18
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.912079/3829, current 268.929352/3830: elapsed=17271.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.929352
last_received_ts = 268.928802
last_seq = 3830
current_ts = 268.946655
current_received_ts = 268.946106
current_seq = 3831
count = 19
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.929352/3830, current 268.946655/3831: elapsed=17291.0us expected=17279.4us +- 86.4us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.946655
last_received_ts = 268.946106
last_seq = 3831
current_ts = 268.963928
current_received_ts = 268.963379
current_seq = 3832
count = 20
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.946655/3831, current 268.963928/3832: elapsed=17278.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.963928
last_received_ts = 268.963379
last_seq = 3832
current_ts = 268.981201
current_received_ts = 268.980652
current_seq = 3833
count = 21
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.963928/3832, current 268.981201/3833: elapsed=17280.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.981201
last_received_ts = 268.980652
last_seq = 3833
current_ts = 268.998474
current_received_ts = 268.997925
current_seq = 3834
count = 22
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.981201/3833, current 268.998474/3834: elapsed=17281.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 268.998474
last_received_ts = 268.997925
last_seq = 3834
current_ts = 269.015747
current_received_ts = 269.015198
current_seq = 3835
count = 23
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 268.998474/3834, current 269.015747/3835: elapsed=17278.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.015747
last_received_ts = 269.015198
last_seq = 3835
current_ts = 269.033051
current_received_ts = 269.032501
current_seq = 3836
count = 24
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.015747/3835, current 269.033051/3836: elapsed=17280.0us expected=17279.4us +- 86.4us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.033051
last_received_ts = 269.032501
last_seq = 3836
current_ts = 269.050262
current_received_ts = 269.049774
current_seq = 3837
count = 25
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.033051/3836, current 269.050262/3837: elapsed=17225.0us expected=17279.4us +- 86.4us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.050262
last_received_ts = 269.049774
last_seq = 3837
current_ts = 269.067474
current_received_ts = 269.066986
current_seq = 3838
count = 26
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.050262/3837, current 269.067474/3838: elapsed=17203.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.067474
last_received_ts = 269.066986
last_seq = 3838
current_ts = 269.084656
current_received_ts = 269.084106
current_seq = 3839
count = 27
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.067474/3838, current 269.084656/3839: elapsed=17194.0us expected=17279.4us +- 86.4us, error 0.5%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.084656
last_received_ts = 269.084106
last_seq = 3839
current_ts = 269.101868
current_received_ts = 269.101288
current_seq = 3840
count = 28
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.084656/3839, current 269.101868/3840: elapsed=17204.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.101868
last_received_ts = 269.101288
last_seq = 3840
current_ts = 269.119080
current_received_ts = 269.118469
current_seq = 3841
count = 29
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.101868/3840, current 269.119080/3841: elapsed=17203.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.119080
last_received_ts = 269.118469
last_seq = 3841
current_ts = 269.136261
current_received_ts = 269.135681
current_seq = 3842
count = 30
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.119080/3841, current 269.136261/3842: elapsed=17205.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.136261
last_received_ts = 269.135681
last_seq = 3842
current_ts = 269.153473
current_received_ts = 269.152863
current_seq = 3843
count = 31
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.136261/3842, current 269.153473/3843: elapsed=17206.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.153473
last_received_ts = 269.152863
last_seq = 3843
current_ts = 269.170685
current_received_ts = 269.170227
current_seq = 3844
count = 32
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.153473/3843, current 269.170685/3844: elapsed=17206.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.170685
last_received_ts = 269.170227
last_seq = 3844
current_ts = 269.187897
current_received_ts = 269.187408
current_seq = 3845
count = 33
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.170685/3844, current 269.187897/3845: elapsed=17216.0us expected=17279.4us +- 86.4us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 269.187897
last_received_ts = 269.187408
last_seq = 3845
current_ts = 269.205109
current_received_ts = 269.204498
current_seq = 3846
count = 34
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 269.187897/3845, current 269.205109/3846: elapsed=17191.0us expected=17279.4us +- 86.4us, error 0.5%
(kms_flip:3839) DEBUG: inconsistent flip ts/seq: last 269.187897/3845, current 269.205109/3846: elapsed=17191.0us expected=17279.4us
(kms_flip:3839) DEBUG: expected 198692, counted 34, encoder type 2
(kms_flip:3839) DEBUG: dropped frames, expected 198692, counted 34, encoder type 2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3839) igt_core-INFO: Stack trace:
(kms_flip:3839) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3839) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3839) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:3839) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:3839) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3839) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3839) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3839) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-HDMI-A2-DP2: FAIL (4.209s)
Starting dynamic subtest: AC-HDMI-A2-DP2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-HDMI-A2-DP2 failed.
**** DEBUG ****
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:3839) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3839) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:3839) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x59444926b210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x59444926b210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x59444939f760, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x59444939f760, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492eb680, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492eb680, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492eb680, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) intel_allocator_simple-DEBUG: <ial: 0x5944492eb680, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3839) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3839) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3839) DEBUG: No stale events found
(kms_flip:3839) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3839) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3839) INFO: Expected frametime: 16667us; measured 17029.4us +- 5.390us accuracy 0.09%
(kms_flip:3839) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17029us +- 5.390us, difference 362.7us (67.3 sigma)
(kms_flip:3839) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 272.944275
current_received_ts = 272.943848
current_seq = 4059
count = 0
seq_step = 1
(kms_flip:3839) DEBUG: name = flip
last_ts = 272.944275
last_received_ts = 272.943848
last_seq = 4059
current_ts = 272.961304
current_received_ts = 272.960754
current_seq = 4060
count = 1
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 272.944275/4059, current 272.961304/4060: elapsed=17036.0us expected=17029.4us +- 85.1us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 272.961304
last_received_ts = 272.960754
last_seq = 4060
current_ts = 272.978333
current_received_ts = 272.977783
current_seq = 4061
count = 2
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 272.961304/4060, current 272.978333/4061: elapsed=17032.0us expected=17029.4us +- 85.1us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 272.978333
last_received_ts = 272.977783
last_seq = 4061
current_ts = 272.995361
current_received_ts = 272.994812
current_seq = 4062
count = 3
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 272.978333/4061, current 272.995361/4062: elapsed=17028.0us expected=17029.4us +- 85.1us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 272.995361
last_received_ts = 272.994812
last_seq = 4062
current_ts = 273.012421
current_received_ts = 273.011841
current_seq = 4063
count = 4
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 272.995361/4062, current 273.012421/4063: elapsed=17033.0us expected=17029.4us +- 85.1us, error 0.0%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.012421
last_received_ts = 273.011841
last_seq = 4063
current_ts = 273.029419
current_received_ts = 273.028900
current_seq = 4064
count = 5
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.012421/4063, current 273.029419/4064: elapsed=17019.0us expected=17029.4us +- 85.1us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.029419
last_received_ts = 273.028900
last_seq = 4064
current_ts = 273.046417
current_received_ts = 273.045959
current_seq = 4065
count = 6
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.029419/4064, current 273.046417/4065: elapsed=17003.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.046417
last_received_ts = 273.045959
last_seq = 4065
current_ts = 273.063416
current_received_ts = 273.062805
current_seq = 4066
count = 7
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.046417/4065, current 273.063416/4066: elapsed=16984.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.063416
last_received_ts = 273.062805
last_seq = 4066
current_ts = 273.080414
current_received_ts = 273.079803
current_seq = 4067
count = 8
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.063416/4066, current 273.080414/4067: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.080414
last_received_ts = 273.079803
last_seq = 4067
current_ts = 273.097382
current_received_ts = 273.096832
current_seq = 4068
count = 9
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.080414/4067, current 273.097382/4068: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.097382
last_received_ts = 273.096832
last_seq = 4068
current_ts = 273.114380
current_received_ts = 273.113922
current_seq = 4069
count = 10
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.097382/4068, current 273.114380/4069: elapsed=16995.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.114380
last_received_ts = 273.113922
last_seq = 4069
current_ts = 273.131348
current_received_ts = 273.130829
current_seq = 4070
count = 11
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.114380/4069, current 273.131348/4070: elapsed=16976.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.131348
last_received_ts = 273.130829
last_seq = 4070
current_ts = 273.148346
current_received_ts = 273.147827
current_seq = 4071
count = 12
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.131348/4070, current 273.148346/4071: elapsed=16988.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.148346
last_received_ts = 273.147827
last_seq = 4071
current_ts = 273.165344
current_received_ts = 273.164795
current_seq = 4072
count = 13
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.148346/4071, current 273.165344/4072: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.165344
last_received_ts = 273.164795
last_seq = 4072
current_ts = 273.182312
current_received_ts = 273.181793
current_seq = 4073
count = 14
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.165344/4072, current 273.182312/4073: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.182312
last_received_ts = 273.181793
last_seq = 4073
current_ts = 273.199310
current_received_ts = 273.198853
current_seq = 4074
count = 15
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.182312/4073, current 273.199310/4074: elapsed=16994.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.199310
last_received_ts = 273.198853
last_seq = 4074
current_ts = 273.216309
current_received_ts = 273.215851
current_seq = 4075
count = 16
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.199310/4074, current 273.216309/4075: elapsed=16984.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.216309
last_received_ts = 273.215851
last_seq = 4075
current_ts = 273.233276
current_received_ts = 273.232727
current_seq = 4076
count = 17
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.216309/4075, current 273.233276/4076: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.233276
last_received_ts = 273.232727
last_seq = 4076
current_ts = 273.250275
current_received_ts = 273.249725
current_seq = 4077
count = 18
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.233276/4076, current 273.250275/4077: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.250275
last_received_ts = 273.249725
last_seq = 4077
current_ts = 273.267242
current_received_ts = 273.266693
current_seq = 4078
count = 19
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.250275/4077, current 273.267242/4078: elapsed=16980.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.267242
last_received_ts = 273.266693
last_seq = 4078
current_ts = 273.284241
current_received_ts = 273.283691
current_seq = 4079
count = 20
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.267242/4078, current 273.284241/4079: elapsed=16983.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.284241
last_received_ts = 273.283691
last_seq = 4079
current_ts = 273.301208
current_received_ts = 273.300690
current_seq = 4080
count = 21
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.284241/4079, current 273.301208/4080: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.301208
last_received_ts = 273.300690
last_seq = 4080
current_ts = 273.318207
current_received_ts = 273.317657
current_seq = 4081
count = 22
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.301208/4080, current 273.318207/4081: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.318207
last_received_ts = 273.317657
last_seq = 4081
current_ts = 273.335205
current_received_ts = 273.334656
current_seq = 4082
count = 23
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.318207/4081, current 273.335205/4082: elapsed=16997.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.335205
last_received_ts = 273.334656
last_seq = 4082
current_ts = 273.352173
current_received_ts = 273.351624
current_seq = 4083
count = 24
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.335205/4082, current 273.352173/4083: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.352173
last_received_ts = 273.351624
last_seq = 4083
current_ts = 273.369171
current_received_ts = 273.368683
current_seq = 4084
count = 25
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.352173/4083, current 273.369171/4084: elapsed=16974.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.369171
last_received_ts = 273.368683
last_seq = 4084
current_ts = 273.386139
current_received_ts = 273.385590
current_seq = 4085
count = 26
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.369171/4084, current 273.386139/4085: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.386139
last_received_ts = 273.385590
last_seq = 4085
current_ts = 273.403137
current_received_ts = 273.402527
current_seq = 4086
count = 27
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.386139/4085, current 273.403137/4086: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.403137
last_received_ts = 273.402527
last_seq = 4086
current_ts = 273.420105
current_received_ts = 273.419495
current_seq = 4087
count = 28
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.403137/4086, current 273.420105/4087: elapsed=16984.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.420105
last_received_ts = 273.419495
last_seq = 4087
current_ts = 273.437103
current_received_ts = 273.436493
current_seq = 4088
count = 29
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.420105/4087, current 273.437103/4088: elapsed=16988.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.437103
last_received_ts = 273.436493
last_seq = 4088
current_ts = 273.454102
current_received_ts = 273.453552
current_seq = 4089
count = 30
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.437103/4088, current 273.454102/4089: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.454102
last_received_ts = 273.453552
last_seq = 4089
current_ts = 273.471069
current_received_ts = 273.470520
current_seq = 4090
count = 31
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.454102/4089, current 273.471069/4090: elapsed=16988.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.471069
last_received_ts = 273.470520
last_seq = 4090
current_ts = 273.488068
current_received_ts = 273.487518
current_seq = 4091
count = 32
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.471069/4090, current 273.488068/4091: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.488068
last_received_ts = 273.487518
last_seq = 4091
current_ts = 273.505035
current_received_ts = 273.504517
current_seq = 4092
count = 33
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.488068/4091, current 273.505035/4092: elapsed=16984.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.505035
last_received_ts = 273.504517
last_seq = 4092
current_ts = 273.522034
current_received_ts = 273.521484
current_seq = 4093
count = 34
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.505035/4092, current 273.522034/4093: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.522034
last_received_ts = 273.521484
last_seq = 4093
current_ts = 273.539001
current_received_ts = 273.538544
current_seq = 4094
count = 35
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.522034/4093, current 273.539001/4094: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.539001
last_received_ts = 273.538544
last_seq = 4094
current_ts = 273.556000
current_received_ts = 273.555481
current_seq = 4095
count = 36
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.539001/4094, current 273.556000/4095: elapsed=16988.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.556000
last_received_ts = 273.555481
last_seq = 4095
current_ts = 273.572998
current_received_ts = 273.572388
current_seq = 4096
count = 37
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.556000/4095, current 273.572998/4096: elapsed=16983.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.572998
last_received_ts = 273.572388
last_seq = 4096
current_ts = 273.589966
current_received_ts = 273.589355
current_seq = 4097
count = 38
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.572998/4096, current 273.589966/4097: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.589966
last_received_ts = 273.589355
last_seq = 4097
current_ts = 273.606964
current_received_ts = 273.606354
current_seq = 4098
count = 39
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.589966/4097, current 273.606964/4098: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.606964
last_received_ts = 273.606354
last_seq = 4098
current_ts = 273.623932
current_received_ts = 273.623322
current_seq = 4099
count = 40
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.606964/4098, current 273.623932/4099: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.623932
last_received_ts = 273.623322
last_seq = 4099
current_ts = 273.640930
current_received_ts = 273.640320
current_seq = 4100
count = 41
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.623932/4099, current 273.640930/4100: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.640930
last_received_ts = 273.640320
last_seq = 4100
current_ts = 273.657928
current_received_ts = 273.657318
current_seq = 4101
count = 42
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.640930/4100, current 273.657928/4101: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.657928
last_received_ts = 273.657318
last_seq = 4101
current_ts = 273.674896
current_received_ts = 273.674286
current_seq = 4102
count = 43
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.657928/4101, current 273.674896/4102: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.674896
last_received_ts = 273.674286
last_seq = 4102
current_ts = 273.691895
current_received_ts = 273.691284
current_seq = 4103
count = 44
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.674896/4102, current 273.691895/4103: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.691895
last_received_ts = 273.691284
last_seq = 4103
current_ts = 273.708862
current_received_ts = 273.708252
current_seq = 4104
count = 45
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.691895/4103, current 273.708862/4104: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.708862
last_received_ts = 273.708252
last_seq = 4104
current_ts = 273.725861
current_received_ts = 273.725250
current_seq = 4105
count = 46
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.708862/4104, current 273.725861/4105: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.725861
last_received_ts = 273.725250
last_seq = 4105
current_ts = 273.742859
current_received_ts = 273.742218
current_seq = 4106
count = 47
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.725861/4105, current 273.742859/4106: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.742859
last_received_ts = 273.742218
last_seq = 4106
current_ts = 273.759827
current_received_ts = 273.759216
current_seq = 4107
count = 48
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.742859/4106, current 273.759827/4107: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.759827
last_received_ts = 273.759216
last_seq = 4107
current_ts = 273.776825
current_received_ts = 273.776215
current_seq = 4108
count = 49
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.759827/4107, current 273.776825/4108: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.776825
last_received_ts = 273.776215
last_seq = 4108
current_ts = 273.793793
current_received_ts = 273.793213
current_seq = 4109
count = 50
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.776825/4108, current 273.793793/4109: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.793793
last_received_ts = 273.793213
last_seq = 4109
current_ts = 273.810791
current_received_ts = 273.810181
current_seq = 4110
count = 51
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.793793/4109, current 273.810791/4110: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.810791
last_received_ts = 273.810181
last_seq = 4110
current_ts = 273.827759
current_received_ts = 273.827179
current_seq = 4111
count = 52
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.810791/4110, current 273.827759/4111: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.827759
last_received_ts = 273.827179
last_seq = 4111
current_ts = 273.844757
current_received_ts = 273.844147
current_seq = 4112
count = 53
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.827759/4111, current 273.844757/4112: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.844757
last_received_ts = 273.844147
last_seq = 4112
current_ts = 273.861755
current_received_ts = 273.861145
current_seq = 4113
count = 54
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.844757/4112, current 273.861755/4113: elapsed=16988.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.861755
last_received_ts = 273.861145
last_seq = 4113
current_ts = 273.878723
current_received_ts = 273.878204
current_seq = 4114
count = 55
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.861755/4113, current 273.878723/4114: elapsed=16985.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.878723
last_received_ts = 273.878204
last_seq = 4114
current_ts = 273.895721
current_received_ts = 273.895203
current_seq = 4115
count = 56
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.878723/4114, current 273.895721/4115: elapsed=16998.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.895721
last_received_ts = 273.895203
last_seq = 4115
current_ts = 273.912720
current_received_ts = 273.912170
current_seq = 4116
count = 57
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.895721/4115, current 273.912720/4116: elapsed=16987.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.912720
last_received_ts = 273.912170
last_seq = 4116
current_ts = 273.929718
current_received_ts = 273.929169
current_seq = 4117
count = 58
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.912720/4116, current 273.929718/4117: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.929718
last_received_ts = 273.929169
last_seq = 4117
current_ts = 273.946686
current_received_ts = 273.946136
current_seq = 4118
count = 59
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.929718/4117, current 273.946686/4118: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.946686
last_received_ts = 273.946136
last_seq = 4118
current_ts = 273.963654
current_received_ts = 273.963135
current_seq = 4119
count = 60
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.946686/4118, current 273.963654/4119: elapsed=16976.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.963654
last_received_ts = 273.963135
last_seq = 4119
current_ts = 273.980652
current_received_ts = 273.980103
current_seq = 4120
count = 61
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.963654/4119, current 273.980652/4120: elapsed=16991.0us expected=17029.4us +- 85.1us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.980652
last_received_ts = 273.980103
last_seq = 4120
current_ts = 273.997650
current_received_ts = 273.997101
current_seq = 4121
count = 62
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.980652/4120, current 273.997650/4121: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 273.997650
last_received_ts = 273.997101
last_seq = 4121
current_ts = 274.014618
current_received_ts = 274.014099
current_seq = 4122
count = 63
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 273.997650/4121, current 274.014618/4122: elapsed=16986.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.014618
last_received_ts = 274.014099
last_seq = 4122
current_ts = 274.031616
current_received_ts = 274.031067
current_seq = 4123
count = 64
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.014618/4122, current 274.031616/4123: elapsed=16976.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.031616
last_received_ts = 274.031067
last_seq = 4123
current_ts = 274.048584
current_received_ts = 274.048035
current_seq = 4124
count = 65
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.031616/4123, current 274.048584/4124: elapsed=16971.0us expected=17029.4us +- 85.1us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.048584
last_received_ts = 274.048035
last_seq = 4124
current_ts = 274.065521
current_received_ts = 274.064972
current_seq = 4125
count = 66
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.048584/4124, current 274.065521/4125: elapsed=16946.0us expected=17029.4us +- 85.1us, error 0.5%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.065521
last_received_ts = 274.064972
last_seq = 4125
current_ts = 274.082458
current_received_ts = 274.081909
current_seq = 4126
count = 67
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.065521/4125, current 274.082458/4126: elapsed=16948.0us expected=17029.4us +- 85.1us, error 0.5%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.082458
last_received_ts = 274.081909
last_seq = 4126
current_ts = 274.099426
current_received_ts = 274.098846
current_seq = 4127
count = 68
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.082458/4126, current 274.099426/4127: elapsed=16947.0us expected=17029.4us +- 85.1us, error 0.5%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.099426
last_received_ts = 274.098846
last_seq = 4127
current_ts = 274.116364
current_received_ts = 274.115814
current_seq = 4128
count = 69
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.099426/4127, current 274.116364/4128: elapsed=16948.0us expected=17029.4us +- 85.1us, error 0.5%
(kms_flip:3839) DEBUG: name = flip
last_ts = 274.116364
last_received_ts = 274.115814
last_seq = 4128
current_ts = 274.133301
current_received_ts = 274.132751
current_seq = 4129
count = 70
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 274.116364/4128, current 274.133301/4129: elapsed=16936.0us expected=17029.4us +- 85.1us, error 0.5%
(kms_flip:3839) DEBUG: inconsistent flip ts/seq: last 274.116364/4128, current 274.133301/4129: elapsed=16936.0us expected=17029.4us
(kms_flip:3839) DEBUG: expected 201610, counted 70, encoder type 2
(kms_flip:3839) DEBUG: dropped frames, expected 201610, counted 70, encoder type 2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3839) igt_core-INFO: Stack trace:
(kms_flip:3839) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3839) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3839) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:3839) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:3839) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3839) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3839) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3839) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-HDMI-A2-DP2: FAIL (4.849s)
Starting dynamic subtest: AD-HDMI-A2-DP2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AD-HDMI-A2-DP2 failed.
**** DEBUG ****
(kms_flip:3839) DEBUG: flip ts/seq: last 279.020752/4411, current 279.037598/4412: elapsed=16845.0us expected=16857.7us +- 84.3us, error 0.1%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.037598
last_received_ts = 279.037048
last_seq = 4412
current_ts = 279.054382
current_received_ts = 279.053864
current_seq = 4413
count = 71
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.037598/4412, current 279.054382/4413: elapsed=16804.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.054382
last_received_ts = 279.053864
last_seq = 4413
current_ts = 279.071228
current_received_ts = 279.070679
current_seq = 4414
count = 72
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.054382/4413, current 279.071228/4414: elapsed=16829.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.071228
last_received_ts = 279.070679
last_seq = 4414
current_ts = 279.088013
current_received_ts = 279.087494
current_seq = 4415
count = 73
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.071228/4414, current 279.088013/4415: elapsed=16805.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.088013
last_received_ts = 279.087494
last_seq = 4415
current_ts = 279.104828
current_received_ts = 279.104309
current_seq = 4416
count = 74
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.088013/4415, current 279.104828/4416: elapsed=16812.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.104828
last_received_ts = 279.104309
last_seq = 4416
current_ts = 279.121674
current_received_ts = 279.121124
current_seq = 4417
count = 75
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.104828/4416, current 279.121674/4417: elapsed=16821.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.121674
last_received_ts = 279.121124
last_seq = 4417
current_ts = 279.138458
current_received_ts = 279.137848
current_seq = 4418
count = 76
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.121674/4417, current 279.138458/4418: elapsed=16810.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.138458
last_received_ts = 279.137848
last_seq = 4418
current_ts = 279.155273
current_received_ts = 279.154663
current_seq = 4419
count = 77
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.138458/4418, current 279.155273/4419: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.155273
last_received_ts = 279.154663
last_seq = 4419
current_ts = 279.172089
current_received_ts = 279.171478
current_seq = 4420
count = 78
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.155273/4419, current 279.172089/4420: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.172089
last_received_ts = 279.171478
last_seq = 4420
current_ts = 279.188904
current_received_ts = 279.188293
current_seq = 4421
count = 79
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.172089/4420, current 279.188904/4421: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.188904
last_received_ts = 279.188293
last_seq = 4421
current_ts = 279.205719
current_received_ts = 279.205109
current_seq = 4422
count = 80
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.188904/4421, current 279.205719/4422: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.205719
last_received_ts = 279.205109
last_seq = 4422
current_ts = 279.222534
current_received_ts = 279.221924
current_seq = 4423
count = 81
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.205719/4422, current 279.222534/4423: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.222534
last_received_ts = 279.221924
last_seq = 4423
current_ts = 279.239349
current_received_ts = 279.238739
current_seq = 4424
count = 82
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.222534/4423, current 279.239349/4424: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.239349
last_received_ts = 279.238739
last_seq = 4424
current_ts = 279.256165
current_received_ts = 279.255554
current_seq = 4425
count = 83
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.239349/4424, current 279.256165/4425: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.256165
last_received_ts = 279.255554
last_seq = 4425
current_ts = 279.272980
current_received_ts = 279.272369
current_seq = 4426
count = 84
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.256165/4425, current 279.272980/4426: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.272980
last_received_ts = 279.272369
last_seq = 4426
current_ts = 279.289795
current_received_ts = 279.289185
current_seq = 4427
count = 85
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.272980/4426, current 279.289795/4427: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.289795
last_received_ts = 279.289185
last_seq = 4427
current_ts = 279.306610
current_received_ts = 279.306061
current_seq = 4428
count = 86
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.289795/4427, current 279.306610/4428: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.306610
last_received_ts = 279.306061
last_seq = 4428
current_ts = 279.323425
current_received_ts = 279.322906
current_seq = 4429
count = 87
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.306610/4428, current 279.323425/4429: elapsed=16819.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.323425
last_received_ts = 279.322906
last_seq = 4429
current_ts = 279.340271
current_received_ts = 279.339691
current_seq = 4430
count = 88
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.323425/4429, current 279.340271/4430: elapsed=16822.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.340271
last_received_ts = 279.339691
last_seq = 4430
current_ts = 279.357056
current_received_ts = 279.356537
current_seq = 4431
count = 89
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.340271/4430, current 279.357056/4431: elapsed=16804.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.357056
last_received_ts = 279.356537
last_seq = 4431
current_ts = 279.373901
current_received_ts = 279.373352
current_seq = 4432
count = 90
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.357056/4431, current 279.373901/4432: elapsed=16825.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.373901
last_received_ts = 279.373352
last_seq = 4432
current_ts = 279.390717
current_received_ts = 279.390137
current_seq = 4433
count = 91
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.373901/4432, current 279.390717/4433: elapsed=16818.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.390717
last_received_ts = 279.390137
last_seq = 4433
current_ts = 279.407532
current_received_ts = 279.406952
current_seq = 4434
count = 92
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.390717/4433, current 279.407532/4434: elapsed=16812.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.407532
last_received_ts = 279.406952
last_seq = 4434
current_ts = 279.424347
current_received_ts = 279.423767
current_seq = 4435
count = 93
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.407532/4434, current 279.424347/4435: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.424347
last_received_ts = 279.423767
last_seq = 4435
current_ts = 279.441162
current_received_ts = 279.440582
current_seq = 4436
count = 94
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.424347/4435, current 279.441162/4436: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.441162
last_received_ts = 279.440582
last_seq = 4436
current_ts = 279.457977
current_received_ts = 279.457397
current_seq = 4437
count = 95
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.441162/4436, current 279.457977/4437: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.457977
last_received_ts = 279.457397
last_seq = 4437
current_ts = 279.474792
current_received_ts = 279.474213
current_seq = 4438
count = 96
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.457977/4437, current 279.474792/4438: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.474792
last_received_ts = 279.474213
last_seq = 4438
current_ts = 279.491608
current_received_ts = 279.491058
current_seq = 4439
count = 97
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.474792/4438, current 279.491608/4439: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.491608
last_received_ts = 279.491058
last_seq = 4439
current_ts = 279.508423
current_received_ts = 279.507843
current_seq = 4440
count = 98
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.491608/4439, current 279.508423/4440: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.508423
last_received_ts = 279.507843
last_seq = 4440
current_ts = 279.525238
current_received_ts = 279.524658
current_seq = 4441
count = 99
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.508423/4440, current 279.525238/4441: elapsed=16816.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.525238
last_received_ts = 279.524658
last_seq = 4441
current_ts = 279.542023
current_received_ts = 279.541504
current_seq = 4442
count = 100
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.525238/4441, current 279.542023/4442: elapsed=16806.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.542023
last_received_ts = 279.541504
last_seq = 4442
current_ts = 279.558868
current_received_ts = 279.558289
current_seq = 4443
count = 101
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.542023/4442, current 279.558868/4443: elapsed=16823.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.558868
last_received_ts = 279.558289
last_seq = 4443
current_ts = 279.575653
current_received_ts = 279.575104
current_seq = 4444
count = 102
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.558868/4443, current 279.575653/4444: elapsed=16813.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.575653
last_received_ts = 279.575104
last_seq = 4444
current_ts = 279.592499
current_received_ts = 279.591919
current_seq = 4445
count = 103
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.575653/4444, current 279.592499/4445: elapsed=16819.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.592499
last_received_ts = 279.591919
last_seq = 4445
current_ts = 279.609283
current_received_ts = 279.608734
current_seq = 4446
count = 104
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.592499/4445, current 279.609283/4446: elapsed=16802.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.609283
last_received_ts = 279.608734
last_seq = 4446
current_ts = 279.626129
current_received_ts = 279.625549
current_seq = 4447
count = 105
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.609283/4446, current 279.626129/4447: elapsed=16827.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.626129
last_received_ts = 279.625549
last_seq = 4447
current_ts = 279.642914
current_received_ts = 279.642365
current_seq = 4448
count = 106
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.626129/4447, current 279.642914/4448: elapsed=16802.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.642914
last_received_ts = 279.642365
last_seq = 4448
current_ts = 279.659729
current_received_ts = 279.659180
current_seq = 4449
count = 107
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.642914/4448, current 279.659729/4449: elapsed=16826.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.659729
last_received_ts = 279.659180
last_seq = 4449
current_ts = 279.676544
current_received_ts = 279.675995
current_seq = 4450
count = 108
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.659729/4449, current 279.676544/4450: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.676544
last_received_ts = 279.675995
last_seq = 4450
current_ts = 279.693390
current_received_ts = 279.692810
current_seq = 4451
count = 109
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.676544/4450, current 279.693390/4451: elapsed=16818.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.693390
last_received_ts = 279.692810
last_seq = 4451
current_ts = 279.710175
current_received_ts = 279.709625
current_seq = 4452
count = 110
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.693390/4451, current 279.710175/4452: elapsed=16812.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.710175
last_received_ts = 279.709625
last_seq = 4452
current_ts = 279.726990
current_received_ts = 279.726440
current_seq = 4453
count = 111
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.710175/4452, current 279.726990/4453: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.726990
last_received_ts = 279.726440
last_seq = 4453
current_ts = 279.743835
current_received_ts = 279.743256
current_seq = 4454
count = 112
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.726990/4453, current 279.743835/4454: elapsed=16817.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.743835
last_received_ts = 279.743256
last_seq = 4454
current_ts = 279.760620
current_received_ts = 279.760101
current_seq = 4455
count = 113
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.743835/4454, current 279.760620/4455: elapsed=16808.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.760620
last_received_ts = 279.760101
last_seq = 4455
current_ts = 279.777435
current_received_ts = 279.776886
current_seq = 4456
count = 114
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.760620/4455, current 279.777435/4456: elapsed=16820.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.777435
last_received_ts = 279.776886
last_seq = 4456
current_ts = 279.794250
current_received_ts = 279.793701
current_seq = 4457
count = 115
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.777435/4456, current 279.794250/4457: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.794250
last_received_ts = 279.793701
last_seq = 4457
current_ts = 279.811096
current_received_ts = 279.810516
current_seq = 4458
count = 116
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.794250/4457, current 279.811096/4458: elapsed=16818.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.811096
last_received_ts = 279.810516
last_seq = 4458
current_ts = 279.827881
current_received_ts = 279.827332
current_seq = 4459
count = 117
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.811096/4458, current 279.827881/4459: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.827881
last_received_ts = 279.827332
last_seq = 4459
current_ts = 279.844696
current_received_ts = 279.844147
current_seq = 4460
count = 118
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.827881/4459, current 279.844696/4460: elapsed=16813.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.844696
last_received_ts = 279.844147
last_seq = 4460
current_ts = 279.861511
current_received_ts = 279.861115
current_seq = 4461
count = 119
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.844696/4460, current 279.861511/4461: elapsed=16806.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.861511
last_received_ts = 279.861115
last_seq = 4461
current_ts = 279.878357
current_received_ts = 279.877869
current_seq = 4462
count = 120
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.861511/4461, current 279.878357/4462: elapsed=16828.0us expected=16857.7us +- 84.3us, error 0.2%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.878357
last_received_ts = 279.877869
last_seq = 4462
current_ts = 279.895142
current_received_ts = 279.894653
current_seq = 4463
count = 121
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.878357/4462, current 279.895142/4463: elapsed=16812.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.895142
last_received_ts = 279.894653
last_seq = 4463
current_ts = 279.911957
current_received_ts = 279.911346
current_seq = 4464
count = 122
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.895142/4463, current 279.911957/4464: elapsed=16805.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.911957
last_received_ts = 279.911346
last_seq = 4464
current_ts = 279.928772
current_received_ts = 279.928162
current_seq = 4465
count = 123
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.911957/4464, current 279.928772/4465: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.928772
last_received_ts = 279.928162
last_seq = 4465
current_ts = 279.945587
current_received_ts = 279.944977
current_seq = 4466
count = 124
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.928772/4465, current 279.945587/4466: elapsed=16814.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.945587
last_received_ts = 279.944977
last_seq = 4466
current_ts = 279.962402
current_received_ts = 279.961792
current_seq = 4467
count = 125
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.945587/4466, current 279.962402/4467: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.962402
last_received_ts = 279.961792
last_seq = 4467
current_ts = 279.979218
current_received_ts = 279.978607
current_seq = 4468
count = 126
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.962402/4467, current 279.979218/4468: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.979218
last_received_ts = 279.978607
last_seq = 4468
current_ts = 279.996033
current_received_ts = 279.995422
current_seq = 4469
count = 127
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.979218/4468, current 279.996033/4469: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 279.996033
last_received_ts = 279.995422
last_seq = 4469
current_ts = 280.012848
current_received_ts = 280.012268
current_seq = 4470
count = 128
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 279.996033/4469, current 280.012848/4470: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.012848
last_received_ts = 280.012268
last_seq = 4470
current_ts = 280.029663
current_received_ts = 280.029083
current_seq = 4471
count = 129
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.012848/4470, current 280.029663/4471: elapsed=16815.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.029663
last_received_ts = 280.029083
last_seq = 4471
current_ts = 280.046478
current_received_ts = 280.045868
current_seq = 4472
count = 130
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.029663/4471, current 280.046478/4472: elapsed=16804.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.046478
last_received_ts = 280.045868
last_seq = 4472
current_ts = 280.063263
current_received_ts = 280.062653
current_seq = 4473
count = 131
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.046478/4472, current 280.063263/4473: elapsed=16799.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.063263
last_received_ts = 280.062653
last_seq = 4473
current_ts = 280.080078
current_received_ts = 280.079468
current_seq = 4474
count = 132
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.063263/4473, current 280.080078/4474: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.080078
last_received_ts = 280.079468
last_seq = 4474
current_ts = 280.096863
current_received_ts = 280.096252
current_seq = 4475
count = 133
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.080078/4474, current 280.096863/4475: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.096863
last_received_ts = 280.096252
last_seq = 4475
current_ts = 280.113647
current_received_ts = 280.113068
current_seq = 4476
count = 134
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.096863/4475, current 280.113647/4476: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.113647
last_received_ts = 280.113068
last_seq = 4476
current_ts = 280.130463
current_received_ts = 280.129852
current_seq = 4477
count = 135
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.113647/4476, current 280.130463/4477: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.130463
last_received_ts = 280.129852
last_seq = 4477
current_ts = 280.147247
current_received_ts = 280.146637
current_seq = 4478
count = 136
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.130463/4477, current 280.147247/4478: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.147247
last_received_ts = 280.146637
last_seq = 4478
current_ts = 280.164062
current_received_ts = 280.163452
current_seq = 4479
count = 137
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.147247/4478, current 280.164062/4479: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.164062
last_received_ts = 280.163452
last_seq = 4479
current_ts = 280.180847
current_received_ts = 280.180237
current_seq = 4480
count = 138
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.164062/4479, current 280.180847/4480: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.180847
last_received_ts = 280.180237
last_seq = 4480
current_ts = 280.197632
current_received_ts = 280.197083
current_seq = 4481
count = 139
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.180847/4480, current 280.197632/4481: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.197632
last_received_ts = 280.197083
last_seq = 4481
current_ts = 280.214447
current_received_ts = 280.213837
current_seq = 4482
count = 140
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.197632/4481, current 280.214447/4482: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.214447
last_received_ts = 280.213837
last_seq = 4482
current_ts = 280.231232
current_received_ts = 280.230621
current_seq = 4483
count = 141
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.214447/4482, current 280.231232/4483: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.231232
last_received_ts = 280.230621
last_seq = 4483
current_ts = 280.248047
current_received_ts = 280.247437
current_seq = 4484
count = 142
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.231232/4483, current 280.248047/4484: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.248047
last_received_ts = 280.247437
last_seq = 4484
current_ts = 280.264862
current_received_ts = 280.264282
current_seq = 4485
count = 143
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.248047/4484, current 280.264862/4485: elapsed=16810.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.264862
last_received_ts = 280.264282
last_seq = 4485
current_ts = 280.281647
current_received_ts = 280.281097
current_seq = 4486
count = 144
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.264862/4485, current 280.281647/4486: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.281647
last_received_ts = 280.281097
last_seq = 4486
current_ts = 280.298462
current_received_ts = 280.297882
current_seq = 4487
count = 145
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.281647/4486, current 280.298462/4487: elapsed=16799.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.298462
last_received_ts = 280.297882
last_seq = 4487
current_ts = 280.315216
current_received_ts = 280.314697
current_seq = 4488
count = 146
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.298462/4487, current 280.315216/4488: elapsed=16784.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.315216
last_received_ts = 280.314697
last_seq = 4488
current_ts = 280.332031
current_received_ts = 280.331482
current_seq = 4489
count = 147
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.315216/4488, current 280.332031/4489: elapsed=16812.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.332031
last_received_ts = 280.331482
last_seq = 4489
current_ts = 280.348846
current_received_ts = 280.348297
current_seq = 4490
count = 148
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.332031/4489, current 280.348846/4490: elapsed=16796.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.348846
last_received_ts = 280.348297
last_seq = 4490
current_ts = 280.365631
current_received_ts = 280.365082
current_seq = 4491
count = 149
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.348846/4490, current 280.365631/4491: elapsed=16793.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.365631
last_received_ts = 280.365082
last_seq = 4491
current_ts = 280.382446
current_received_ts = 280.381866
current_seq = 4492
count = 150
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.365631/4491, current 280.382446/4492: elapsed=16803.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.382446
last_received_ts = 280.381866
last_seq = 4492
current_ts = 280.399231
current_received_ts = 280.398682
current_seq = 4493
count = 151
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.382446/4492, current 280.399231/4493: elapsed=16787.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.399231
last_received_ts = 280.398682
last_seq = 4493
current_ts = 280.416016
current_received_ts = 280.415466
current_seq = 4494
count = 152
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.399231/4493, current 280.416016/4494: elapsed=16795.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.416016
last_received_ts = 280.415466
last_seq = 4494
current_ts = 280.432831
current_received_ts = 280.432281
current_seq = 4495
count = 153
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.416016/4494, current 280.432831/4495: elapsed=16810.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.432831
last_received_ts = 280.432281
last_seq = 4495
current_ts = 280.449615
current_received_ts = 280.449066
current_seq = 4496
count = 154
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.432831/4495, current 280.449615/4496: elapsed=16796.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.449615
last_received_ts = 280.449066
last_seq = 4496
current_ts = 280.466431
current_received_ts = 280.465851
current_seq = 4497
count = 155
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.449615/4496, current 280.466431/4497: elapsed=16800.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.466431
last_received_ts = 280.465851
last_seq = 4497
current_ts = 280.483215
current_received_ts = 280.482666
current_seq = 4498
count = 156
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.466431/4497, current 280.483215/4498: elapsed=16788.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.483215
last_received_ts = 280.482666
last_seq = 4498
current_ts = 280.500031
current_received_ts = 280.499451
current_seq = 4499
count = 157
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.483215/4498, current 280.500031/4499: elapsed=16807.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.500031
last_received_ts = 280.499451
last_seq = 4499
current_ts = 280.516815
current_received_ts = 280.516266
current_seq = 4500
count = 158
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.500031/4499, current 280.516815/4500: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.516815
last_received_ts = 280.516266
last_seq = 4500
current_ts = 280.533600
current_received_ts = 280.533051
current_seq = 4501
count = 159
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.516815/4500, current 280.533600/4501: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.533600
last_received_ts = 280.533051
last_seq = 4501
current_ts = 280.550415
current_received_ts = 280.549866
current_seq = 4502
count = 160
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.533600/4501, current 280.550415/4502: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.550415
last_received_ts = 280.549866
last_seq = 4502
current_ts = 280.567200
current_received_ts = 280.566650
current_seq = 4503
count = 161
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.550415/4502, current 280.567200/4503: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.567200
last_received_ts = 280.566650
last_seq = 4503
current_ts = 280.584015
current_received_ts = 280.583435
current_seq = 4504
count = 162
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.567200/4503, current 280.584015/4504: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.584015
last_received_ts = 280.583435
last_seq = 4504
current_ts = 280.600800
current_received_ts = 280.600250
current_seq = 4505
count = 163
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.584015/4504, current 280.600800/4505: elapsed=16789.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.600800
last_received_ts = 280.600250
last_seq = 4505
current_ts = 280.617615
current_received_ts = 280.617065
current_seq = 4506
count = 164
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.600800/4505, current 280.617615/4506: elapsed=16806.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.617615
last_received_ts = 280.617065
last_seq = 4506
current_ts = 280.634399
current_received_ts = 280.633850
current_seq = 4507
count = 165
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.617615/4506, current 280.634399/4507: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.634399
last_received_ts = 280.633850
last_seq = 4507
current_ts = 280.651184
current_received_ts = 280.650635
current_seq = 4508
count = 166
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.634399/4507, current 280.651184/4508: elapsed=16796.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.651184
last_received_ts = 280.650635
last_seq = 4508
current_ts = 280.667999
current_received_ts = 280.667450
current_seq = 4509
count = 167
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.651184/4508, current 280.667999/4509: elapsed=16799.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.667999
last_received_ts = 280.667450
last_seq = 4509
current_ts = 280.684784
current_received_ts = 280.684235
current_seq = 4510
count = 168
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.667999/4509, current 280.684784/4510: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.684784
last_received_ts = 280.684235
last_seq = 4510
current_ts = 280.701569
current_received_ts = 280.701050
current_seq = 4511
count = 169
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.684784/4510, current 280.701569/4511: elapsed=16787.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.701569
last_received_ts = 280.701050
last_seq = 4511
current_ts = 280.718384
current_received_ts = 280.717834
current_seq = 4512
count = 170
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.701569/4511, current 280.718384/4512: elapsed=16807.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.718384
last_received_ts = 280.717834
last_seq = 4512
current_ts = 280.735168
current_received_ts = 280.734619
current_seq = 4513
count = 171
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.718384/4512, current 280.735168/4513: elapsed=16790.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.735168
last_received_ts = 280.734619
last_seq = 4513
current_ts = 280.751984
current_received_ts = 280.751434
current_seq = 4514
count = 172
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.735168/4513, current 280.751984/4514: elapsed=16802.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.751984
last_received_ts = 280.751434
last_seq = 4514
current_ts = 280.768768
current_received_ts = 280.768219
current_seq = 4515
count = 173
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.751984/4514, current 280.768768/4515: elapsed=16803.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.768768
last_received_ts = 280.768219
last_seq = 4515
current_ts = 280.785553
current_received_ts = 280.785034
current_seq = 4516
count = 174
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.768768/4515, current 280.785553/4516: elapsed=16787.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.785553
last_received_ts = 280.785034
last_seq = 4516
current_ts = 280.802368
current_received_ts = 280.801819
current_seq = 4517
count = 175
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.785553/4516, current 280.802368/4517: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.802368
last_received_ts = 280.801819
last_seq = 4517
current_ts = 280.819153
current_received_ts = 280.818695
current_seq = 4518
count = 176
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.802368/4517, current 280.819153/4518: elapsed=16797.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.819153
last_received_ts = 280.818695
last_seq = 4518
current_ts = 280.835968
current_received_ts = 280.835419
current_seq = 4519
count = 177
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.819153/4518, current 280.835968/4519: elapsed=16805.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.835968
last_received_ts = 280.835419
last_seq = 4519
current_ts = 280.852753
current_received_ts = 280.852142
current_seq = 4520
count = 178
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.835968/4519, current 280.852753/4520: elapsed=16789.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.852753
last_received_ts = 280.852142
last_seq = 4520
current_ts = 280.869568
current_received_ts = 280.869019
current_seq = 4521
count = 179
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.852753/4520, current 280.869568/4521: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.869568
last_received_ts = 280.869019
last_seq = 4521
current_ts = 280.886353
current_received_ts = 280.885803
current_seq = 4522
count = 180
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.869568/4521, current 280.886353/4522: elapsed=16804.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.886353
last_received_ts = 280.885803
last_seq = 4522
current_ts = 280.903168
current_received_ts = 280.902588
current_seq = 4523
count = 181
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.886353/4522, current 280.903168/4523: elapsed=16802.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.903168
last_received_ts = 280.902588
last_seq = 4523
current_ts = 280.919952
current_received_ts = 280.919464
current_seq = 4524
count = 182
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.903168/4523, current 280.919952/4524: elapsed=16792.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.919952
last_received_ts = 280.919464
last_seq = 4524
current_ts = 280.936737
current_received_ts = 280.936157
current_seq = 4525
count = 183
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.919952/4524, current 280.936737/4525: elapsed=16794.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.936737
last_received_ts = 280.936157
last_seq = 4525
current_ts = 280.953552
current_received_ts = 280.952942
current_seq = 4526
count = 184
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.936737/4525, current 280.953552/4526: elapsed=16796.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.953552
last_received_ts = 280.952942
last_seq = 4526
current_ts = 280.970337
current_received_ts = 280.969727
current_seq = 4527
count = 185
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.953552/4526, current 280.970337/4527: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.970337
last_received_ts = 280.969727
last_seq = 4527
current_ts = 280.987152
current_received_ts = 280.986542
current_seq = 4528
count = 186
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.970337/4527, current 280.987152/4528: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 280.987152
last_received_ts = 280.986542
last_seq = 4528
current_ts = 281.003937
current_received_ts = 281.003418
current_seq = 4529
count = 187
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 280.987152/4528, current 281.003937/4529: elapsed=16798.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 281.003937
last_received_ts = 281.003418
last_seq = 4529
current_ts = 281.020752
current_received_ts = 281.020203
current_seq = 4530
count = 188
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 281.003937/4529, current 281.020752/4530: elapsed=16809.0us expected=16857.7us +- 84.3us, error 0.3%
(kms_flip:3839) DEBUG: name = flip
last_ts = 281.020752
last_received_ts = 281.020203
last_seq = 4530
current_ts = 281.037537
current_received_ts = 281.036987
current_seq = 4531
count = 189
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 281.020752/4530, current 281.037537/4531: elapsed=16795.0us expected=16857.7us +- 84.3us, error 0.4%
(kms_flip:3839) DEBUG: name = flip
last_ts = 281.037537
last_received_ts = 281.036987
last_seq = 4531
current_ts = 281.054321
current_received_ts = 281.053772
current_seq = 4532
count = 190
seq_step = 1
(kms_flip:3839) DEBUG: flip ts/seq: last 281.037537/4531, current 281.054321/4532: elapsed=16773.0us expected=16857.7us +- 84.3us, error 0.5%
(kms_flip:3839) DEBUG: inconsistent flip ts/seq: last 281.037537/4531, current 281.054321/4532: elapsed=16773.0us expected=16857.7us
(kms_flip:3839) DEBUG: expected 203663, counted 190, encoder type 2
(kms_flip:3839) DEBUG: dropped frames, expected 203663, counted 190, encoder type 2
(kms_flip:3839) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3839) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3839) igt_core-INFO: Stack trace:
(kms_flip:3839) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3839) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3839) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:3839) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:3839) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3839) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3839) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3839) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AD-HDMI-A2-DP2: FAIL (7.152s)
Starting dynamic subtest: BC-HDMI-A2-DP2
Dynamic subtest BC-HDMI-A2-DP2: SUCCESS (5.629s)
Starting dynamic subtest: BD-HDMI-A2-DP2
Dynamic subtest BD-HDMI-A2-DP2: SUCCESS (5.637s)
Starting dynamic subtest: CD-HDMI-A2-DP2
Dynamic subtest CD-HDMI-A2-DP2: SUCCESS (5.645s)
Subtest 2x-plain-flip-fb-recreate: FAIL (33.177s)