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

shard-bmg-1

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

Using IGT_SRANDOM=1739261159 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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16149.3us +- 27.268us accuracy 0.51%
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AB-DP2-HDMI-A3: FAIL (0.696s)
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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16202.3us +- 5.422us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16202us +- 5.422us, difference 464.4us (85.7 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AC-DP2-HDMI-A3: FAIL (5.062s)
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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16424.7us +- 5.871us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16425us +- 5.871us, difference 241.9us (41.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1930 run_pair()
  #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest AD-DP2-HDMI-A3: FAIL (6.253s)
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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16554.1us +- 4.334us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16554us +- 4.334us, difference 112.5us (26.0 sigma)
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.703s)
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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16611.9us +- 5.297us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16612us +- 5.297us, difference 54.7us (10.3 sigma)
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.664s)
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 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16636.2us +- 4.916us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16636us +- 4.916us, difference 30.5us (6.2 sigma)
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.659s)
Subtest 2x-plain-flip-ts-check: FAIL (29.083s)

Starting subtest: 2x-plain-flip-ts-check
Starting dynamic subtest: AB-DP2-HDMI-A3
(kms_flip:7571) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:7571) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
Dynamic subtest AB-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:7571) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:7571) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46175950, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46175950, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46183c80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46183c80, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f461ba030, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f461ba030, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f4617f730, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f4617f730, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7571) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7571) DEBUG: No stale events found
(kms_flip:7571) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7571) INFO: Expected frametime: 16667us; measured 16149.3us +- 27.268us accuracy 0.51%
(kms_flip:7571) CRITICAL: Test assertion failure function calibrate_ts, file ../tests/kms_flip.c:1454:
(kms_flip:7571) CRITICAL: Failed assertion: 3 * stddev / mean < 0.005
(kms_flip:7571) igt_core-INFO: Stack trace:
(kms_flip:7571) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7571) igt_core-INFO:   #1 ../tests/kms_flip.c:1728 run_test_on_crtc_set.constprop.0()
(kms_flip:7571) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7571) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7571) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7571) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7571) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7571) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AB-DP2-HDMI-A3: FAIL (0.696s)
Starting dynamic subtest: AC-DP2-HDMI-A3
(kms_flip:7571) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7571) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AC-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:7571) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:7571) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:7571) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f4617fd00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f4617fd00, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f461d7370, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f461d7370, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46180210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46180210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46180210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) intel_allocator_simple-DEBUG: <ial: 0x5b1f46180210, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:7571) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7571) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:7571) DEBUG: No stale events found
(kms_flip:7571) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:7571) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:7571) INFO: Expected frametime: 16667us; measured 16202.3us +- 5.422us accuracy 0.10%
(kms_flip:7571) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16202us +- 5.422us, difference 464.4us (85.7 sigma)
(kms_flip:7571) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 271.590576
current_received_ts = 271.590057
current_seq = 11352
count = 0
seq_step = 1
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.590576
last_received_ts = 271.590057
last_seq = 11352
current_ts = 271.606781
current_received_ts = 271.606171
current_seq = 11353
count = 1
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.590576/11352, current 271.606781/11353: elapsed=16196.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.606781
last_received_ts = 271.606171
last_seq = 11353
current_ts = 271.622986
current_received_ts = 271.622375
current_seq = 11354
count = 2
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.606781/11353, current 271.622986/11354: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.622986
last_received_ts = 271.622375
last_seq = 11354
current_ts = 271.639191
current_received_ts = 271.638580
current_seq = 11355
count = 3
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.622986/11354, current 271.639191/11355: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.639191
last_received_ts = 271.638580
last_seq = 11355
current_ts = 271.655396
current_received_ts = 271.654785
current_seq = 11356
count = 4
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.639191/11355, current 271.655396/11356: elapsed=16201.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.655396
last_received_ts = 271.654785
last_seq = 11356
current_ts = 271.671600
current_received_ts = 271.670990
current_seq = 11357
count = 5
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.655396/11356, current 271.671600/11357: elapsed=16203.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.671600
last_received_ts = 271.670990
last_seq = 11357
current_ts = 271.687805
current_received_ts = 271.687195
current_seq = 11358
count = 6
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.671600/11357, current 271.687805/11358: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.687805
last_received_ts = 271.687195
last_seq = 11358
current_ts = 271.703979
current_received_ts = 271.703400
current_seq = 11359
count = 7
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.687805/11358, current 271.703979/11359: elapsed=16201.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.703979
last_received_ts = 271.703400
last_seq = 11359
current_ts = 271.720184
current_received_ts = 271.719574
current_seq = 11360
count = 8
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.703979/11359, current 271.720184/11360: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.720184
last_received_ts = 271.719574
last_seq = 11360
current_ts = 271.736389
current_received_ts = 271.735809
current_seq = 11361
count = 9
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.720184/11360, current 271.736389/11361: elapsed=16203.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.736389
last_received_ts = 271.735809
last_seq = 11361
current_ts = 271.752594
current_received_ts = 271.751984
current_seq = 11362
count = 10
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.736389/11361, current 271.752594/11362: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.752594
last_received_ts = 271.751984
last_seq = 11362
current_ts = 271.768799
current_received_ts = 271.768188
current_seq = 11363
count = 11
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.752594/11362, current 271.768799/11363: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.768799
last_received_ts = 271.768188
last_seq = 11363
current_ts = 271.785004
current_received_ts = 271.784393
current_seq = 11364
count = 12
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.768799/11363, current 271.785004/11364: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.785004
last_received_ts = 271.784393
last_seq = 11364
current_ts = 271.801208
current_received_ts = 271.800598
current_seq = 11365
count = 13
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.785004/11364, current 271.801208/11365: elapsed=16201.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.801208
last_received_ts = 271.800598
last_seq = 11365
current_ts = 271.817413
current_received_ts = 271.816803
current_seq = 11366
count = 14
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.801208/11365, current 271.817413/11366: elapsed=16207.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.817413
last_received_ts = 271.816803
last_seq = 11366
current_ts = 271.833618
current_received_ts = 271.833038
current_seq = 11367
count = 15
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.817413/11366, current 271.833618/11367: elapsed=16198.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.833618
last_received_ts = 271.833038
last_seq = 11367
current_ts = 271.849823
current_received_ts = 271.849213
current_seq = 11368
count = 16
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.833618/11367, current 271.849823/11368: elapsed=16201.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.849823
last_received_ts = 271.849213
last_seq = 11368
current_ts = 271.866028
current_received_ts = 271.865417
current_seq = 11369
count = 17
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.849823/11368, current 271.866028/11369: elapsed=16202.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.866028
last_received_ts = 271.865417
last_seq = 11369
current_ts = 271.882233
current_received_ts = 271.881622
current_seq = 11370
count = 18
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.866028/11369, current 271.882233/11370: elapsed=16208.0us expected=16202.3us +- 81.0us, error 0.0%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.882233
last_received_ts = 271.881622
last_seq = 11370
current_ts = 271.898468
current_received_ts = 271.898071
current_seq = 11371
count = 19
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.882233/11370, current 271.898468/11371: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.898468
last_received_ts = 271.898071
last_seq = 11371
current_ts = 271.914734
current_received_ts = 271.914154
current_seq = 11372
count = 20
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.898468/11371, current 271.914734/11372: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.914734
last_received_ts = 271.914154
last_seq = 11372
current_ts = 271.931000
current_received_ts = 271.930389
current_seq = 11373
count = 21
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.914734/11372, current 271.931000/11373: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.931000
last_received_ts = 271.930389
last_seq = 11373
current_ts = 271.947266
current_received_ts = 271.946747
current_seq = 11374
count = 22
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.931000/11373, current 271.947266/11374: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.947266
last_received_ts = 271.946747
last_seq = 11374
current_ts = 271.963531
current_received_ts = 271.962982
current_seq = 11375
count = 23
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.947266/11374, current 271.963531/11375: elapsed=16258.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.963531
last_received_ts = 271.962982
last_seq = 11375
current_ts = 271.979767
current_received_ts = 271.979248
current_seq = 11376
count = 24
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.963531/11375, current 271.979767/11376: elapsed=16261.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.979767
last_received_ts = 271.979248
last_seq = 11376
current_ts = 271.996033
current_received_ts = 271.995514
current_seq = 11377
count = 25
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.979767/11376, current 271.996033/11377: elapsed=16257.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 271.996033
last_received_ts = 271.995514
last_seq = 11377
current_ts = 272.012299
current_received_ts = 272.011780
current_seq = 11378
count = 26
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 271.996033/11377, current 272.012299/11378: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.012299
last_received_ts = 272.011780
last_seq = 11378
current_ts = 272.028564
current_received_ts = 272.028046
current_seq = 11379
count = 27
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.012299/11378, current 272.028564/11379: elapsed=16255.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.028564
last_received_ts = 272.028046
last_seq = 11379
current_ts = 272.044830
current_received_ts = 272.044281
current_seq = 11380
count = 28
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.028564/11379, current 272.044830/11380: elapsed=16263.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.044830
last_received_ts = 272.044281
last_seq = 11380
current_ts = 272.061066
current_received_ts = 272.060516
current_seq = 11381
count = 29
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.044830/11380, current 272.061066/11381: elapsed=16248.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.061066
last_received_ts = 272.060516
last_seq = 11381
current_ts = 272.077332
current_received_ts = 272.076782
current_seq = 11382
count = 30
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.061066/11381, current 272.077332/11382: elapsed=16263.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.077332
last_received_ts = 272.076782
last_seq = 11382
current_ts = 272.093597
current_received_ts = 272.093048
current_seq = 11383
count = 31
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.077332/11382, current 272.093597/11383: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.093597
last_received_ts = 272.093048
last_seq = 11383
current_ts = 272.109863
current_received_ts = 272.109314
current_seq = 11384
count = 32
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.093597/11383, current 272.109863/11384: elapsed=16254.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.109863
last_received_ts = 272.109314
last_seq = 11384
current_ts = 272.126099
current_received_ts = 272.125580
current_seq = 11385
count = 33
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.109863/11384, current 272.126099/11385: elapsed=16256.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.126099
last_received_ts = 272.125580
last_seq = 11385
current_ts = 272.142365
current_received_ts = 272.141815
current_seq = 11386
count = 34
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.126099/11385, current 272.142365/11386: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.142365
last_received_ts = 272.141815
last_seq = 11386
current_ts = 272.158630
current_received_ts = 272.158081
current_seq = 11387
count = 35
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.142365/11386, current 272.158630/11387: elapsed=16257.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.158630
last_received_ts = 272.158081
last_seq = 11387
current_ts = 272.174896
current_received_ts = 272.174347
current_seq = 11388
count = 36
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.158630/11387, current 272.174896/11388: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.174896
last_received_ts = 272.174347
last_seq = 11388
current_ts = 272.191132
current_received_ts = 272.190613
current_seq = 11389
count = 37
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.174896/11388, current 272.191132/11389: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.191132
last_received_ts = 272.190613
last_seq = 11389
current_ts = 272.207397
current_received_ts = 272.206848
current_seq = 11390
count = 38
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.191132/11389, current 272.207397/11390: elapsed=16268.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.207397
last_received_ts = 272.206848
last_seq = 11390
current_ts = 272.223663
current_received_ts = 272.223114
current_seq = 11391
count = 39
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.207397/11390, current 272.223663/11391: elapsed=16255.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.223663
last_received_ts = 272.223114
last_seq = 11391
current_ts = 272.239929
current_received_ts = 272.239380
current_seq = 11392
count = 40
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.223663/11391, current 272.239929/11392: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.239929
last_received_ts = 272.239380
last_seq = 11392
current_ts = 272.256195
current_received_ts = 272.255646
current_seq = 11393
count = 41
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.239929/11392, current 272.256195/11393: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.256195
last_received_ts = 272.255646
last_seq = 11393
current_ts = 272.272461
current_received_ts = 272.271881
current_seq = 11394
count = 42
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.256195/11393, current 272.272461/11394: elapsed=16258.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.272461
last_received_ts = 272.271881
last_seq = 11394
current_ts = 272.288696
current_received_ts = 272.288147
current_seq = 11395
count = 43
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.272461/11394, current 272.288696/11395: elapsed=16253.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.288696
last_received_ts = 272.288147
last_seq = 11395
current_ts = 272.304962
current_received_ts = 272.304413
current_seq = 11396
count = 44
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.288696/11395, current 272.304962/11396: elapsed=16263.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.304962
last_received_ts = 272.304413
last_seq = 11396
current_ts = 272.321228
current_received_ts = 272.320679
current_seq = 11397
count = 45
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.304962/11396, current 272.321228/11397: elapsed=16252.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.321228
last_received_ts = 272.320679
last_seq = 11397
current_ts = 272.337494
current_received_ts = 272.336914
current_seq = 11398
count = 46
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.321228/11397, current 272.337494/11398: elapsed=16270.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.337494
last_received_ts = 272.336914
last_seq = 11398
current_ts = 272.353729
current_received_ts = 272.353149
current_seq = 11399
count = 47
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.337494/11398, current 272.353729/11399: elapsed=16253.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.353729
last_received_ts = 272.353149
last_seq = 11399
current_ts = 272.369995
current_received_ts = 272.369446
current_seq = 11400
count = 48
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.353729/11399, current 272.369995/11400: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.369995
last_received_ts = 272.369446
last_seq = 11400
current_ts = 272.386261
current_received_ts = 272.385712
current_seq = 11401
count = 49
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.369995/11400, current 272.386261/11401: elapsed=16252.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.386261
last_received_ts = 272.385712
last_seq = 11401
current_ts = 272.402527
current_received_ts = 272.401978
current_seq = 11402
count = 50
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.386261/11401, current 272.402527/11402: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.402527
last_received_ts = 272.401978
last_seq = 11402
current_ts = 272.418762
current_received_ts = 272.418243
current_seq = 11403
count = 51
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.402527/11402, current 272.418762/11403: elapsed=16257.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.418762
last_received_ts = 272.418243
last_seq = 11403
current_ts = 272.435028
current_received_ts = 272.434479
current_seq = 11404
count = 52
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.418762/11403, current 272.435028/11404: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.435028
last_received_ts = 272.434479
last_seq = 11404
current_ts = 272.451294
current_received_ts = 272.450745
current_seq = 11405
count = 53
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.435028/11404, current 272.451294/11405: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.451294
last_received_ts = 272.450745
last_seq = 11405
current_ts = 272.467560
current_received_ts = 272.467041
current_seq = 11406
count = 54
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.451294/11405, current 272.467560/11406: elapsed=16263.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.467560
last_received_ts = 272.467041
last_seq = 11406
current_ts = 272.483826
current_received_ts = 272.483215
current_seq = 11407
count = 55
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.467560/11406, current 272.483826/11407: elapsed=16253.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.483826
last_received_ts = 272.483215
last_seq = 11407
current_ts = 272.500061
current_received_ts = 272.499542
current_seq = 11408
count = 56
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.483826/11407, current 272.500061/11408: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.500061
last_received_ts = 272.499542
last_seq = 11408
current_ts = 272.516327
current_received_ts = 272.515778
current_seq = 11409
count = 57
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.500061/11408, current 272.516327/11409: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.516327
last_received_ts = 272.515778
last_seq = 11409
current_ts = 272.532593
current_received_ts = 272.532074
current_seq = 11410
count = 58
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.516327/11409, current 272.532593/11410: elapsed=16256.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.532593
last_received_ts = 272.532074
last_seq = 11410
current_ts = 272.548859
current_received_ts = 272.548309
current_seq = 11411
count = 59
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.532593/11410, current 272.548859/11411: elapsed=16261.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.548859
last_received_ts = 272.548309
last_seq = 11411
current_ts = 272.565094
current_received_ts = 272.564514
current_seq = 11412
count = 60
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.548859/11411, current 272.565094/11412: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.565094
last_received_ts = 272.564514
last_seq = 11412
current_ts = 272.581360
current_received_ts = 272.580811
current_seq = 11413
count = 61
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.565094/11412, current 272.581360/11413: elapsed=16253.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.581360
last_received_ts = 272.580811
last_seq = 11413
current_ts = 272.597626
current_received_ts = 272.597076
current_seq = 11414
count = 62
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.581360/11413, current 272.597626/11414: elapsed=16264.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.597626
last_received_ts = 272.597076
last_seq = 11414
current_ts = 272.613892
current_received_ts = 272.613342
current_seq = 11415
count = 63
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.597626/11414, current 272.613892/11415: elapsed=16266.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.613892
last_received_ts = 272.613342
last_seq = 11415
current_ts = 272.630127
current_received_ts = 272.629608
current_seq = 11416
count = 64
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.613892/11415, current 272.630127/11416: elapsed=16250.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.630127
last_received_ts = 272.629608
last_seq = 11416
current_ts = 272.646393
current_received_ts = 272.645844
current_seq = 11417
count = 65
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.630127/11416, current 272.646393/11417: elapsed=16258.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.646393
last_received_ts = 272.645844
last_seq = 11417
current_ts = 272.662659
current_received_ts = 272.662140
current_seq = 11418
count = 66
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.646393/11417, current 272.662659/11418: elapsed=16270.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.662659
last_received_ts = 272.662140
last_seq = 11418
current_ts = 272.678925
current_received_ts = 272.678375
current_seq = 11419
count = 67
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.662659/11418, current 272.678925/11419: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.678925
last_received_ts = 272.678375
last_seq = 11419
current_ts = 272.695190
current_received_ts = 272.694641
current_seq = 11420
count = 68
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.678925/11419, current 272.695190/11420: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.695190
last_received_ts = 272.694641
last_seq = 11420
current_ts = 272.711456
current_received_ts = 272.710876
current_seq = 11421
count = 69
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.695190/11420, current 272.711456/11421: elapsed=16258.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.711456
last_received_ts = 272.710876
last_seq = 11421
current_ts = 272.727692
current_received_ts = 272.727142
current_seq = 11422
count = 70
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.711456/11421, current 272.727692/11422: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.727692
last_received_ts = 272.727142
last_seq = 11422
current_ts = 272.743958
current_received_ts = 272.743408
current_seq = 11423
count = 71
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.727692/11422, current 272.743958/11423: elapsed=16261.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.743958
last_received_ts = 272.743408
last_seq = 11423
current_ts = 272.760223
current_received_ts = 272.759674
current_seq = 11424
count = 72
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.743958/11423, current 272.760223/11424: elapsed=16257.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.760223
last_received_ts = 272.759674
last_seq = 11424
current_ts = 272.776489
current_received_ts = 272.775940
current_seq = 11425
count = 73
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.760223/11424, current 272.776489/11425: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.776489
last_received_ts = 272.775940
last_seq = 11425
current_ts = 272.792725
current_received_ts = 272.792145
current_seq = 11426
count = 74
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.776489/11425, current 272.792725/11426: elapsed=16255.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.792725
last_received_ts = 272.792145
last_seq = 11426
current_ts = 272.808990
current_received_ts = 272.808380
current_seq = 11427
count = 75
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.792725/11426, current 272.808990/11427: elapsed=16257.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.808990
last_received_ts = 272.808380
last_seq = 11427
current_ts = 272.825256
current_received_ts = 272.824646
current_seq = 11428
count = 76
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.808990/11427, current 272.825256/11428: elapsed=16260.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.825256
last_received_ts = 272.824646
last_seq = 11428
current_ts = 272.841522
current_received_ts = 272.840912
current_seq = 11429
count = 77
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.825256/11428, current 272.841522/11429: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.841522
last_received_ts = 272.840912
last_seq = 11429
current_ts = 272.857758
current_received_ts = 272.857178
current_seq = 11430
count = 78
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.841522/11429, current 272.857758/11430: elapsed=16259.0us expected=16202.3us +- 81.0us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.857758
last_received_ts = 272.857178
last_seq = 11430
current_ts = 272.874023
current_received_ts = 272.873413
current_seq = 11431
count = 79
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.857758/11430, current 272.874023/11431: elapsed=16258.0us expected=16202.3us +- 81.0us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 272.874023
last_received_ts = 272.873413
last_seq = 11431
current_ts = 272.890320
current_received_ts = 272.889709
current_seq = 11432
count = 80
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 272.874023/11431, current 272.890320/11432: elapsed=16290.0us expected=16202.3us +- 81.0us, error 0.5%
(kms_flip:7571) DEBUG: inconsistent flip ts/seq: last 272.874023/11431, current 272.890320/11432: elapsed=16290.0us expected=16202.3us
(kms_flip:7571) DEBUG: expected 238395, counted 80, encoder type 2
(kms_flip:7571) DEBUG: dropped frames, expected 238395, counted 80, encoder type 2
(kms_flip:7571) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7571) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7571) igt_core-INFO: Stack trace:
(kms_flip:7571) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7571) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7571) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7571) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7571) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7571) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7571) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7571) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-DP2-HDMI-A3: FAIL (5.062s)
Starting dynamic subtest: AD-DP2-HDMI-A3
(kms_flip:7571) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7571) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest AD-DP2-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:7571) DEBUG: flip ts/seq: last 276.967468/11665, current 276.983917/11666: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 276.983917
last_received_ts = 276.983337
last_seq = 11666
current_ts = 277.000366
current_received_ts = 276.999756
current_seq = 11667
count = 26
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 276.983917/11666, current 277.000366/11667: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.000366
last_received_ts = 276.999756
last_seq = 11667
current_ts = 277.016846
current_received_ts = 277.016235
current_seq = 11668
count = 27
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.000366/11667, current 277.016846/11668: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.016846
last_received_ts = 277.016235
last_seq = 11668
current_ts = 277.033295
current_received_ts = 277.032684
current_seq = 11669
count = 28
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.016846/11668, current 277.033295/11669: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.033295
last_received_ts = 277.032684
last_seq = 11669
current_ts = 277.049744
current_received_ts = 277.049164
current_seq = 11670
count = 29
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.033295/11669, current 277.049744/11670: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.049744
last_received_ts = 277.049164
last_seq = 11670
current_ts = 277.066193
current_received_ts = 277.065613
current_seq = 11671
count = 30
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.049744/11670, current 277.066193/11671: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.066193
last_received_ts = 277.065613
last_seq = 11671
current_ts = 277.082642
current_received_ts = 277.082062
current_seq = 11672
count = 31
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.066193/11671, current 277.082642/11672: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.082642
last_received_ts = 277.082062
last_seq = 11672
current_ts = 277.099091
current_received_ts = 277.098511
current_seq = 11673
count = 32
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.082642/11672, current 277.099091/11673: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.099091
last_received_ts = 277.098511
last_seq = 11673
current_ts = 277.115570
current_received_ts = 277.114960
current_seq = 11674
count = 33
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.099091/11673, current 277.115570/11674: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.115570
last_received_ts = 277.114960
last_seq = 11674
current_ts = 277.132019
current_received_ts = 277.131409
current_seq = 11675
count = 34
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.115570/11674, current 277.132019/11675: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.132019
last_received_ts = 277.131409
last_seq = 11675
current_ts = 277.148468
current_received_ts = 277.147858
current_seq = 11676
count = 35
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.132019/11675, current 277.148468/11676: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.148468
last_received_ts = 277.147858
last_seq = 11676
current_ts = 277.164917
current_received_ts = 277.164307
current_seq = 11677
count = 36
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.148468/11676, current 277.164917/11677: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.164917
last_received_ts = 277.164307
last_seq = 11677
current_ts = 277.181366
current_received_ts = 277.180786
current_seq = 11678
count = 37
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.164917/11677, current 277.181366/11678: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.181366
last_received_ts = 277.180786
last_seq = 11678
current_ts = 277.197815
current_received_ts = 277.197327
current_seq = 11679
count = 38
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.181366/11678, current 277.197815/11679: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.197815
last_received_ts = 277.197327
last_seq = 11679
current_ts = 277.214294
current_received_ts = 277.213837
current_seq = 11680
count = 39
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.197815/11679, current 277.214294/11680: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.214294
last_received_ts = 277.213837
last_seq = 11680
current_ts = 277.230743
current_received_ts = 277.230133
current_seq = 11681
count = 40
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.214294/11680, current 277.230743/11681: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.230743
last_received_ts = 277.230133
last_seq = 11681
current_ts = 277.247192
current_received_ts = 277.246582
current_seq = 11682
count = 41
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.230743/11681, current 277.247192/11682: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.247192
last_received_ts = 277.246582
last_seq = 11682
current_ts = 277.263641
current_received_ts = 277.263062
current_seq = 11683
count = 42
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.247192/11682, current 277.263641/11683: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.263641
last_received_ts = 277.263062
last_seq = 11683
current_ts = 277.280090
current_received_ts = 277.279480
current_seq = 11684
count = 43
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.263641/11683, current 277.280090/11684: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.280090
last_received_ts = 277.279480
last_seq = 11684
current_ts = 277.296539
current_received_ts = 277.296112
current_seq = 11685
count = 44
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.280090/11684, current 277.296539/11685: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.296539
last_received_ts = 277.296112
last_seq = 11685
current_ts = 277.313019
current_received_ts = 277.312500
current_seq = 11686
count = 45
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.296539/11685, current 277.313019/11686: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.313019
last_received_ts = 277.312500
last_seq = 11686
current_ts = 277.329468
current_received_ts = 277.328979
current_seq = 11687
count = 46
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.313019/11686, current 277.329468/11687: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.329468
last_received_ts = 277.328979
last_seq = 11687
current_ts = 277.345917
current_received_ts = 277.345306
current_seq = 11688
count = 47
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.329468/11687, current 277.345917/11688: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.345917
last_received_ts = 277.345306
last_seq = 11688
current_ts = 277.362366
current_received_ts = 277.361755
current_seq = 11689
count = 48
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.345917/11688, current 277.362366/11689: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.362366
last_received_ts = 277.361755
last_seq = 11689
current_ts = 277.378815
current_received_ts = 277.378204
current_seq = 11690
count = 49
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.362366/11689, current 277.378815/11690: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.378815
last_received_ts = 277.378204
last_seq = 11690
current_ts = 277.395264
current_received_ts = 277.394684
current_seq = 11691
count = 50
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.378815/11690, current 277.395264/11691: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.395264
last_received_ts = 277.394684
last_seq = 11691
current_ts = 277.411743
current_received_ts = 277.411133
current_seq = 11692
count = 51
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.395264/11691, current 277.411743/11692: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.411743
last_received_ts = 277.411133
last_seq = 11692
current_ts = 277.428192
current_received_ts = 277.427582
current_seq = 11693
count = 52
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.411743/11692, current 277.428192/11693: elapsed=16458.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.428192
last_received_ts = 277.427582
last_seq = 11693
current_ts = 277.444641
current_received_ts = 277.444031
current_seq = 11694
count = 53
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.428192/11693, current 277.444641/11694: elapsed=16450.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.444641
last_received_ts = 277.444031
last_seq = 11694
current_ts = 277.461090
current_received_ts = 277.460480
current_seq = 11695
count = 54
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.444641/11694, current 277.461090/11695: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.461090
last_received_ts = 277.460480
last_seq = 11695
current_ts = 277.477539
current_received_ts = 277.476959
current_seq = 11696
count = 55
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.461090/11695, current 277.477539/11696: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.477539
last_received_ts = 277.476959
last_seq = 11696
current_ts = 277.493988
current_received_ts = 277.493408
current_seq = 11697
count = 56
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.477539/11696, current 277.493988/11697: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.493988
last_received_ts = 277.493408
last_seq = 11697
current_ts = 277.510468
current_received_ts = 277.509857
current_seq = 11698
count = 57
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.493988/11697, current 277.510468/11698: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.510468
last_received_ts = 277.509857
last_seq = 11698
current_ts = 277.526917
current_received_ts = 277.526306
current_seq = 11699
count = 58
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.510468/11698, current 277.526917/11699: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.526917
last_received_ts = 277.526306
last_seq = 11699
current_ts = 277.543365
current_received_ts = 277.542786
current_seq = 11700
count = 59
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.526917/11699, current 277.543365/11700: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.543365
last_received_ts = 277.542786
last_seq = 11700
current_ts = 277.559814
current_received_ts = 277.559204
current_seq = 11701
count = 60
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.543365/11700, current 277.559814/11701: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.559814
last_received_ts = 277.559204
last_seq = 11701
current_ts = 277.576263
current_received_ts = 277.575653
current_seq = 11702
count = 61
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.559814/11701, current 277.576263/11702: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.576263
last_received_ts = 277.575653
last_seq = 11702
current_ts = 277.592712
current_received_ts = 277.592133
current_seq = 11703
count = 62
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.576263/11702, current 277.592712/11703: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.592712
last_received_ts = 277.592133
last_seq = 11703
current_ts = 277.609192
current_received_ts = 277.608582
current_seq = 11704
count = 63
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.592712/11703, current 277.609192/11704: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.609192
last_received_ts = 277.608582
last_seq = 11704
current_ts = 277.625641
current_received_ts = 277.625031
current_seq = 11705
count = 64
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.609192/11704, current 277.625641/11705: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.625641
last_received_ts = 277.625031
last_seq = 11705
current_ts = 277.642090
current_received_ts = 277.641479
current_seq = 11706
count = 65
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.625641/11705, current 277.642090/11706: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.642090
last_received_ts = 277.641479
last_seq = 11706
current_ts = 277.658539
current_received_ts = 277.657959
current_seq = 11707
count = 66
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.642090/11706, current 277.658539/11707: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.658539
last_received_ts = 277.657959
last_seq = 11707
current_ts = 277.674988
current_received_ts = 277.674377
current_seq = 11708
count = 67
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.658539/11707, current 277.674988/11708: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.674988
last_received_ts = 277.674377
last_seq = 11708
current_ts = 277.691437
current_received_ts = 277.690857
current_seq = 11709
count = 68
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.674988/11708, current 277.691437/11709: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.691437
last_received_ts = 277.690857
last_seq = 11709
current_ts = 277.707916
current_received_ts = 277.707306
current_seq = 11710
count = 69
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.691437/11709, current 277.707916/11710: elapsed=16455.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.707916
last_received_ts = 277.707306
last_seq = 11710
current_ts = 277.724365
current_received_ts = 277.723785
current_seq = 11711
count = 70
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.707916/11710, current 277.724365/11711: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.724365
last_received_ts = 277.723785
last_seq = 11711
current_ts = 277.740814
current_received_ts = 277.740204
current_seq = 11712
count = 71
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.724365/11711, current 277.740814/11712: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.740814
last_received_ts = 277.740204
last_seq = 11712
current_ts = 277.757263
current_received_ts = 277.756653
current_seq = 11713
count = 72
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.740814/11712, current 277.757263/11713: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.757263
last_received_ts = 277.756653
last_seq = 11713
current_ts = 277.773712
current_received_ts = 277.773102
current_seq = 11714
count = 73
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.757263/11713, current 277.773712/11714: elapsed=16453.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.773712
last_received_ts = 277.773102
last_seq = 11714
current_ts = 277.790161
current_received_ts = 277.789581
current_seq = 11715
count = 74
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.773712/11714, current 277.790161/11715: elapsed=16458.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.790161
last_received_ts = 277.789581
last_seq = 11715
current_ts = 277.806641
current_received_ts = 277.806030
current_seq = 11716
count = 75
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.790161/11715, current 277.806641/11716: elapsed=16451.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.806641
last_received_ts = 277.806030
last_seq = 11716
current_ts = 277.823090
current_received_ts = 277.822479
current_seq = 11717
count = 76
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.806641/11716, current 277.823090/11717: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.823090
last_received_ts = 277.822479
last_seq = 11717
current_ts = 277.839539
current_received_ts = 277.838928
current_seq = 11718
count = 77
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.823090/11717, current 277.839539/11718: elapsed=16457.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.839539
last_received_ts = 277.838928
last_seq = 11718
current_ts = 277.855988
current_received_ts = 277.855377
current_seq = 11719
count = 78
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.839539/11718, current 277.855988/11719: elapsed=16451.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.855988
last_received_ts = 277.855377
last_seq = 11719
current_ts = 277.872437
current_received_ts = 277.871826
current_seq = 11720
count = 79
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.855988/11719, current 277.872437/11720: elapsed=16454.0us expected=16424.7us +- 82.1us, error 0.2%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.872437
last_received_ts = 277.871826
last_seq = 11720
current_ts = 277.888916
current_received_ts = 277.888306
current_seq = 11721
count = 80
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.872437/11720, current 277.888916/11721: elapsed=16467.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.888916
last_received_ts = 277.888306
last_seq = 11721
current_ts = 277.905396
current_received_ts = 277.904785
current_seq = 11722
count = 81
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.888916/11721, current 277.905396/11722: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.905396
last_received_ts = 277.904785
last_seq = 11722
current_ts = 277.921875
current_received_ts = 277.921265
current_seq = 11723
count = 82
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.905396/11722, current 277.921875/11723: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.921875
last_received_ts = 277.921265
last_seq = 11723
current_ts = 277.938354
current_received_ts = 277.937744
current_seq = 11724
count = 83
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.921875/11723, current 277.938354/11724: elapsed=16481.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.938354
last_received_ts = 277.937744
last_seq = 11724
current_ts = 277.954834
current_received_ts = 277.954224
current_seq = 11725
count = 84
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.938354/11724, current 277.954834/11725: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.954834
last_received_ts = 277.954224
last_seq = 11725
current_ts = 277.971313
current_received_ts = 277.970703
current_seq = 11726
count = 85
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.954834/11725, current 277.971313/11726: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.971313
last_received_ts = 277.970703
last_seq = 11726
current_ts = 277.987793
current_received_ts = 277.987183
current_seq = 11727
count = 86
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.971313/11726, current 277.987793/11727: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 277.987793
last_received_ts = 277.987183
last_seq = 11727
current_ts = 278.004272
current_received_ts = 278.003662
current_seq = 11728
count = 87
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 277.987793/11727, current 278.004272/11728: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.004272
last_received_ts = 278.003662
last_seq = 11728
current_ts = 278.020752
current_received_ts = 278.020142
current_seq = 11729
count = 88
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.004272/11728, current 278.020752/11729: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.020752
last_received_ts = 278.020142
last_seq = 11729
current_ts = 278.037231
current_received_ts = 278.036621
current_seq = 11730
count = 89
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.020752/11729, current 278.037231/11730: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.037231
last_received_ts = 278.036621
last_seq = 11730
current_ts = 278.053711
current_received_ts = 278.053101
current_seq = 11731
count = 90
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.037231/11730, current 278.053711/11731: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.053711
last_received_ts = 278.053101
last_seq = 11731
current_ts = 278.070190
current_received_ts = 278.069580
current_seq = 11732
count = 91
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.053711/11731, current 278.070190/11732: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.070190
last_received_ts = 278.069580
last_seq = 11732
current_ts = 278.086670
current_received_ts = 278.086090
current_seq = 11733
count = 92
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.070190/11732, current 278.086670/11733: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.086670
last_received_ts = 278.086090
last_seq = 11733
current_ts = 278.103149
current_received_ts = 278.102539
current_seq = 11734
count = 93
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.086670/11733, current 278.103149/11734: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.103149
last_received_ts = 278.102539
last_seq = 11734
current_ts = 278.119629
current_received_ts = 278.119049
current_seq = 11735
count = 94
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.103149/11734, current 278.119629/11735: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.119629
last_received_ts = 278.119049
last_seq = 11735
current_ts = 278.136108
current_received_ts = 278.135651
current_seq = 11736
count = 95
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.119629/11735, current 278.136108/11736: elapsed=16481.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.136108
last_received_ts = 278.135651
last_seq = 11736
current_ts = 278.152588
current_received_ts = 278.152191
current_seq = 11737
count = 96
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.136108/11736, current 278.152588/11737: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.152588
last_received_ts = 278.152191
last_seq = 11737
current_ts = 278.169067
current_received_ts = 278.168579
current_seq = 11738
count = 97
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.152588/11737, current 278.169067/11738: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.169067
last_received_ts = 278.168579
last_seq = 11738
current_ts = 278.185547
current_received_ts = 278.184937
current_seq = 11739
count = 98
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.169067/11738, current 278.185547/11739: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.185547
last_received_ts = 278.184937
last_seq = 11739
current_ts = 278.202026
current_received_ts = 278.201416
current_seq = 11740
count = 99
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.185547/11739, current 278.202026/11740: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.202026
last_received_ts = 278.201416
last_seq = 11740
current_ts = 278.218506
current_received_ts = 278.217896
current_seq = 11741
count = 100
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.202026/11740, current 278.218506/11741: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.218506
last_received_ts = 278.217896
last_seq = 11741
current_ts = 278.234985
current_received_ts = 278.234375
current_seq = 11742
count = 101
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.218506/11741, current 278.234985/11742: elapsed=16483.0us expected=16424.7us +- 82.1us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.234985
last_received_ts = 278.234375
last_seq = 11742
current_ts = 278.251465
current_received_ts = 278.250854
current_seq = 11743
count = 102
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.234985/11742, current 278.251465/11743: elapsed=16477.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.251465
last_received_ts = 278.250854
last_seq = 11743
current_ts = 278.267944
current_received_ts = 278.267456
current_seq = 11744
count = 103
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.251465/11743, current 278.267944/11744: elapsed=16487.0us expected=16424.7us +- 82.1us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.267944
last_received_ts = 278.267456
last_seq = 11744
current_ts = 278.284424
current_received_ts = 278.283936
current_seq = 11745
count = 104
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.267944/11744, current 278.284424/11745: elapsed=16470.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.284424
last_received_ts = 278.283936
last_seq = 11745
current_ts = 278.300903
current_received_ts = 278.300354
current_seq = 11746
count = 105
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.284424/11745, current 278.300903/11746: elapsed=16487.0us expected=16424.7us +- 82.1us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.300903
last_received_ts = 278.300354
last_seq = 11746
current_ts = 278.317383
current_received_ts = 278.316925
current_seq = 11747
count = 106
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.300903/11746, current 278.317383/11747: elapsed=16475.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.317383
last_received_ts = 278.316925
last_seq = 11747
current_ts = 278.333862
current_received_ts = 278.333282
current_seq = 11748
count = 107
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.317383/11747, current 278.333862/11748: elapsed=16478.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.333862
last_received_ts = 278.333282
last_seq = 11748
current_ts = 278.350342
current_received_ts = 278.349731
current_seq = 11749
count = 108
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.333862/11748, current 278.350342/11749: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.350342
last_received_ts = 278.349731
last_seq = 11749
current_ts = 278.366821
current_received_ts = 278.366211
current_seq = 11750
count = 109
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.350342/11749, current 278.366821/11750: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.366821
last_received_ts = 278.366211
last_seq = 11750
current_ts = 278.383301
current_received_ts = 278.382721
current_seq = 11751
count = 110
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.366821/11750, current 278.383301/11751: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.383301
last_received_ts = 278.382721
last_seq = 11751
current_ts = 278.399780
current_received_ts = 278.399292
current_seq = 11752
count = 111
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.383301/11751, current 278.399780/11752: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.399780
last_received_ts = 278.399292
last_seq = 11752
current_ts = 278.416260
current_received_ts = 278.415680
current_seq = 11753
count = 112
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.399780/11752, current 278.416260/11753: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.416260
last_received_ts = 278.415680
last_seq = 11753
current_ts = 278.432739
current_received_ts = 278.432129
current_seq = 11754
count = 113
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.416260/11753, current 278.432739/11754: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.432739
last_received_ts = 278.432129
last_seq = 11754
current_ts = 278.449219
current_received_ts = 278.448608
current_seq = 11755
count = 114
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.432739/11754, current 278.449219/11755: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.449219
last_received_ts = 278.448608
last_seq = 11755
current_ts = 278.465698
current_received_ts = 278.465088
current_seq = 11756
count = 115
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.449219/11755, current 278.465698/11756: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.465698
last_received_ts = 278.465088
last_seq = 11756
current_ts = 278.482178
current_received_ts = 278.481567
current_seq = 11757
count = 116
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.465698/11756, current 278.482178/11757: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.482178
last_received_ts = 278.481567
last_seq = 11757
current_ts = 278.498657
current_received_ts = 278.498077
current_seq = 11758
count = 117
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.482178/11757, current 278.498657/11758: elapsed=16485.0us expected=16424.7us +- 82.1us, error 0.4%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.498657
last_received_ts = 278.498077
last_seq = 11758
current_ts = 278.515137
current_received_ts = 278.514526
current_seq = 11759
count = 118
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.498657/11758, current 278.515137/11759: elapsed=16476.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.515137
last_received_ts = 278.514526
last_seq = 11759
current_ts = 278.531616
current_received_ts = 278.531036
current_seq = 11760
count = 119
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.515137/11759, current 278.531616/11760: elapsed=16478.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.531616
last_received_ts = 278.531036
last_seq = 11760
current_ts = 278.548096
current_received_ts = 278.547485
current_seq = 11761
count = 120
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.531616/11760, current 278.548096/11761: elapsed=16481.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.548096
last_received_ts = 278.547485
last_seq = 11761
current_ts = 278.564575
current_received_ts = 278.563965
current_seq = 11762
count = 121
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.548096/11761, current 278.564575/11762: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.564575
last_received_ts = 278.563965
last_seq = 11762
current_ts = 278.581055
current_received_ts = 278.580597
current_seq = 11763
count = 122
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.564575/11762, current 278.581055/11763: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.581055
last_received_ts = 278.580597
last_seq = 11763
current_ts = 278.597534
current_received_ts = 278.596954
current_seq = 11764
count = 123
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.581055/11763, current 278.597534/11764: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.597534
last_received_ts = 278.596954
last_seq = 11764
current_ts = 278.614014
current_received_ts = 278.613403
current_seq = 11765
count = 124
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.597534/11764, current 278.614014/11765: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.614014
last_received_ts = 278.613403
last_seq = 11765
current_ts = 278.630493
current_received_ts = 278.629913
current_seq = 11766
count = 125
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.614014/11765, current 278.630493/11766: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.630493
last_received_ts = 278.629913
last_seq = 11766
current_ts = 278.646973
current_received_ts = 278.646393
current_seq = 11767
count = 126
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.630493/11766, current 278.646973/11767: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.646973
last_received_ts = 278.646393
last_seq = 11767
current_ts = 278.663452
current_received_ts = 278.662842
current_seq = 11768
count = 127
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.646973/11767, current 278.663452/11768: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.663452
last_received_ts = 278.662842
last_seq = 11768
current_ts = 278.679932
current_received_ts = 278.679474
current_seq = 11769
count = 128
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.663452/11768, current 278.679932/11769: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.679932
last_received_ts = 278.679474
last_seq = 11769
current_ts = 278.696411
current_received_ts = 278.695831
current_seq = 11770
count = 129
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.679932/11769, current 278.696411/11770: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.696411
last_received_ts = 278.695831
last_seq = 11770
current_ts = 278.712891
current_received_ts = 278.712280
current_seq = 11771
count = 130
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.696411/11770, current 278.712891/11771: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.712891
last_received_ts = 278.712280
last_seq = 11771
current_ts = 278.729370
current_received_ts = 278.728790
current_seq = 11772
count = 131
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.712891/11771, current 278.729370/11772: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.729370
last_received_ts = 278.728790
last_seq = 11772
current_ts = 278.745850
current_received_ts = 278.745239
current_seq = 11773
count = 132
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.729370/11772, current 278.745850/11773: elapsed=16478.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.745850
last_received_ts = 278.745239
last_seq = 11773
current_ts = 278.762329
current_received_ts = 278.761719
current_seq = 11774
count = 133
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.745850/11773, current 278.762329/11774: elapsed=16481.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.762329
last_received_ts = 278.761719
last_seq = 11774
current_ts = 278.778809
current_received_ts = 278.778198
current_seq = 11775
count = 134
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.762329/11774, current 278.778809/11775: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.778809
last_received_ts = 278.778198
last_seq = 11775
current_ts = 278.795288
current_received_ts = 278.794678
current_seq = 11776
count = 135
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.778809/11775, current 278.795288/11776: elapsed=16479.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.795288
last_received_ts = 278.794678
last_seq = 11776
current_ts = 278.811768
current_received_ts = 278.811157
current_seq = 11777
count = 136
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.795288/11776, current 278.811768/11777: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.811768
last_received_ts = 278.811157
last_seq = 11777
current_ts = 278.828247
current_received_ts = 278.827637
current_seq = 11778
count = 137
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.811768/11777, current 278.828247/11778: elapsed=16481.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.828247
last_received_ts = 278.827637
last_seq = 11778
current_ts = 278.844727
current_received_ts = 278.844116
current_seq = 11779
count = 138
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.828247/11778, current 278.844727/11779: elapsed=16478.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.844727
last_received_ts = 278.844116
last_seq = 11779
current_ts = 278.861206
current_received_ts = 278.860626
current_seq = 11780
count = 139
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.844727/11779, current 278.861206/11780: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.861206
last_received_ts = 278.860626
last_seq = 11780
current_ts = 278.877686
current_received_ts = 278.877106
current_seq = 11781
count = 140
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.861206/11780, current 278.877686/11781: elapsed=16480.0us expected=16424.7us +- 82.1us, error 0.3%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.877686
last_received_ts = 278.877106
last_seq = 11781
current_ts = 278.894196
current_received_ts = 278.893585
current_seq = 11782
count = 141
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.877686/11781, current 278.894196/11782: elapsed=16499.0us expected=16424.7us +- 82.1us, error 0.5%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.894196
last_received_ts = 278.893585
last_seq = 11782
current_ts = 278.910706
current_received_ts = 278.910095
current_seq = 11783
count = 142
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.894196/11782, current 278.910706/11783: elapsed=16502.0us expected=16424.7us +- 82.1us, error 0.5%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.910706
last_received_ts = 278.910095
last_seq = 11783
current_ts = 278.927185
current_received_ts = 278.926605
current_seq = 11784
count = 143
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.910706/11783, current 278.927185/11784: elapsed=16503.0us expected=16424.7us +- 82.1us, error 0.5%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.927185
last_received_ts = 278.926605
last_seq = 11784
current_ts = 278.943695
current_received_ts = 278.943085
current_seq = 11785
count = 144
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.927185/11784, current 278.943695/11785: elapsed=16501.0us expected=16424.7us +- 82.1us, error 0.5%
(kms_flip:7571) DEBUG: name = flip
last_ts = 278.943695
last_received_ts = 278.943085
last_seq = 11785
current_ts = 278.960205
current_received_ts = 278.959625
current_seq = 11786
count = 145
seq_step = 1
(kms_flip:7571) DEBUG: flip ts/seq: last 278.943695/11785, current 278.960205/11786: elapsed=16511.0us expected=16424.7us +- 82.1us, error 0.5%
(kms_flip:7571) DEBUG: inconsistent flip ts/seq: last 278.943695/11785, current 278.960205/11786: elapsed=16511.0us expected=16424.7us
(kms_flip:7571) DEBUG: expected 235166, counted 145, encoder type 2
(kms_flip:7571) DEBUG: dropped frames, expected 235166, counted 145, encoder type 2
(kms_flip:7571) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:7571) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:7571) igt_core-INFO: Stack trace:
(kms_flip:7571) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:7571) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:7571) igt_core-INFO:   #2 ../tests/kms_flip.c:1930 run_pair()
(kms_flip:7571) igt_core-INFO:   #3 ../tests/kms_flip.c:2087 __igt_unique____real_main2001()
(kms_flip:7571) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:7571) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7571) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7571) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AD-DP2-HDMI-A3: FAIL (6.253s)
Starting dynamic subtest: BC-DP2-HDMI-A3
Dynamic subtest BC-DP2-HDMI-A3: SUCCESS (5.703s)
Starting dynamic subtest: BD-DP2-HDMI-A3
Dynamic subtest BD-DP2-HDMI-A3: SUCCESS (5.664s)
Starting dynamic subtest: CD-DP2-HDMI-A3
Dynamic subtest CD-DP2-HDMI-A3: SUCCESS (5.659s)
Subtest 2x-plain-flip-ts-check: FAIL (29.083s)