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

shard-dg2-432

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

Using IGT_SRANDOM=1741475570 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17212.7us +- 6.688us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 17213us +- 6.688us, difference 546.1us (81.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A2: FAIL (4.897s)
Starting dynamic subtest: B-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16951.6us +- 4.589us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16952us +- 4.589us, difference 284.9us (62.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A2: FAIL (6.214s)
Starting dynamic subtest: C-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16798.9us +- 6.049us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16799us +- 6.049us, difference 132.3us (21.9 sigma)
Dynamic subtest C-HDMI-A2: SUCCESS (4.212s)
Starting dynamic subtest: D-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16744.6us +- 9.591us accuracy 0.17%
vblank interval differs from modeline! expected 16666.7us, measured 16745us +- 9.591us, difference 78.0us (8.1 sigma)
Dynamic subtest D-HDMI-A2: SUCCESS (4.247s)
Starting dynamic subtest: A-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16713.2us +- 5.695us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16713us +- 5.695us, difference 46.5us (8.2 sigma)
Dynamic subtest A-DP2: SUCCESS (4.292s)
Starting dynamic subtest: B-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16697.8us +- 7.993us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16698us +- 7.993us, difference 31.1us (3.9 sigma)
Dynamic subtest B-DP2: SUCCESS (4.256s)
Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16692.9us +- 6.884us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16693us +- 6.884us, difference 26.3us (3.8 sigma)
Dynamic subtest C-DP2: SUCCESS (4.260s)
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16689.0us +- 8.124us accuracy 0.15%
vblank interval differs from modeline! expected 16666.7us, measured 16689us +- 8.124us, difference 22.3us (2.7 sigma)
Dynamic subtest D-DP2: SUCCESS (4.258s)
Subtest plain-flip-ts-check: FAIL (36.660s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
(kms_flip:3860) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3860) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3860) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3860) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3860) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3860) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3860) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3860) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3860) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd6f770, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd6f770, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd7cfb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd7cfb0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd79bc0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd79bc0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd7c380, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) intel_allocator_simple-DEBUG: <ial: 0x6015dfd7c380, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3860) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3860) DEBUG: No stale events found
(kms_flip:3860) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3860) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3860) INFO: Expected frametime: 16667us; measured 17212.7us +- 6.688us accuracy 0.12%
(kms_flip:3860) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17213us +- 6.688us, difference 546.1us (81.6 sigma)
(kms_flip:3860) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 168.497253
current_received_ts = 168.496796
current_seq = 5333
count = 0
seq_step = 1
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.497253
last_received_ts = 168.496796
last_seq = 5333
current_ts = 168.514465
current_received_ts = 168.513992
current_seq = 5334
count = 1
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.497253/5333, current 168.514465/5334: elapsed=17211.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.514465
last_received_ts = 168.513992
last_seq = 5334
current_ts = 168.531677
current_received_ts = 168.531219
current_seq = 5335
count = 2
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.514465/5334, current 168.531677/5335: elapsed=17222.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.531677
last_received_ts = 168.531219
last_seq = 5335
current_ts = 168.548904
current_received_ts = 168.548477
current_seq = 5336
count = 3
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.531677/5335, current 168.548904/5336: elapsed=17215.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.548904
last_received_ts = 168.548477
last_seq = 5336
current_ts = 168.566101
current_received_ts = 168.565689
current_seq = 5337
count = 4
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.548904/5336, current 168.566101/5337: elapsed=17207.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.566101
last_received_ts = 168.565689
last_seq = 5337
current_ts = 168.583313
current_received_ts = 168.582840
current_seq = 5338
count = 5
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.566101/5337, current 168.583313/5338: elapsed=17211.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.583313
last_received_ts = 168.582840
last_seq = 5338
current_ts = 168.600540
current_received_ts = 168.600006
current_seq = 5339
count = 6
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.583313/5338, current 168.600540/5339: elapsed=17225.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.600540
last_received_ts = 168.600006
last_seq = 5339
current_ts = 168.617752
current_received_ts = 168.617203
current_seq = 5340
count = 7
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.600540/5339, current 168.617752/5340: elapsed=17214.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.617752
last_received_ts = 168.617203
last_seq = 5340
current_ts = 168.634949
current_received_ts = 168.634415
current_seq = 5341
count = 8
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.617752/5340, current 168.634949/5341: elapsed=17199.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.634949
last_received_ts = 168.634415
last_seq = 5341
current_ts = 168.652176
current_received_ts = 168.651627
current_seq = 5342
count = 9
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.634949/5341, current 168.652176/5342: elapsed=17227.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.652176
last_received_ts = 168.651627
last_seq = 5342
current_ts = 168.669388
current_received_ts = 168.668839
current_seq = 5343
count = 10
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.652176/5342, current 168.669388/5343: elapsed=17214.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.669388
last_received_ts = 168.668839
last_seq = 5343
current_ts = 168.686600
current_received_ts = 168.686066
current_seq = 5344
count = 11
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.669388/5343, current 168.686600/5344: elapsed=17199.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.686600
last_received_ts = 168.686066
last_seq = 5344
current_ts = 168.703812
current_received_ts = 168.703278
current_seq = 5345
count = 12
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.686600/5344, current 168.703812/5345: elapsed=17218.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.703812
last_received_ts = 168.703278
last_seq = 5345
current_ts = 168.721024
current_received_ts = 168.720490
current_seq = 5346
count = 13
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.703812/5345, current 168.721024/5346: elapsed=17215.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.721024
last_received_ts = 168.720490
last_seq = 5346
current_ts = 168.738251
current_received_ts = 168.737701
current_seq = 5347
count = 14
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.721024/5346, current 168.738251/5347: elapsed=17220.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.738251
last_received_ts = 168.737701
last_seq = 5347
current_ts = 168.755463
current_received_ts = 168.754913
current_seq = 5348
count = 15
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.738251/5347, current 168.755463/5348: elapsed=17213.0us expected=17212.7us +- 86.1us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.755463
last_received_ts = 168.754913
last_seq = 5348
current_ts = 168.772659
current_received_ts = 168.772125
current_seq = 5349
count = 16
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.755463/5348, current 168.772659/5349: elapsed=17199.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.772659
last_received_ts = 168.772125
last_seq = 5349
current_ts = 168.789886
current_received_ts = 168.789337
current_seq = 5350
count = 17
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.772659/5349, current 168.789886/5350: elapsed=17226.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.789886
last_received_ts = 168.789337
last_seq = 5350
current_ts = 168.807083
current_received_ts = 168.806549
current_seq = 5351
count = 18
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.789886/5350, current 168.807083/5351: elapsed=17202.0us expected=17212.7us +- 86.1us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.807083
last_received_ts = 168.806549
last_seq = 5351
current_ts = 168.824249
current_received_ts = 168.823700
current_seq = 5352
count = 19
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.807083/5351, current 168.824249/5352: elapsed=17157.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.824249
last_received_ts = 168.823700
last_seq = 5352
current_ts = 168.841400
current_received_ts = 168.840866
current_seq = 5353
count = 20
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.824249/5352, current 168.841400/5353: elapsed=17150.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.841400
last_received_ts = 168.840866
last_seq = 5353
current_ts = 168.858551
current_received_ts = 168.858002
current_seq = 5354
count = 21
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.841400/5353, current 168.858551/5354: elapsed=17150.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.858551
last_received_ts = 168.858002
last_seq = 5354
current_ts = 168.875687
current_received_ts = 168.875153
current_seq = 5355
count = 22
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.858551/5354, current 168.875687/5355: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.875687
last_received_ts = 168.875153
last_seq = 5355
current_ts = 168.892838
current_received_ts = 168.892303
current_seq = 5356
count = 23
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.875687/5355, current 168.892838/5356: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.892838
last_received_ts = 168.892303
last_seq = 5356
current_ts = 168.909973
current_received_ts = 168.909439
current_seq = 5357
count = 24
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.892838/5356, current 168.909973/5357: elapsed=17139.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.909973
last_received_ts = 168.909439
last_seq = 5357
current_ts = 168.927124
current_received_ts = 168.926590
current_seq = 5358
count = 25
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.909973/5357, current 168.927124/5358: elapsed=17150.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.927124
last_received_ts = 168.926590
last_seq = 5358
current_ts = 168.944260
current_received_ts = 168.943726
current_seq = 5359
count = 26
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.927124/5358, current 168.944260/5359: elapsed=17140.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.944260
last_received_ts = 168.943726
last_seq = 5359
current_ts = 168.961411
current_received_ts = 168.960892
current_seq = 5360
count = 27
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.944260/5359, current 168.961411/5360: elapsed=17152.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.961411
last_received_ts = 168.960892
last_seq = 5360
current_ts = 168.978561
current_received_ts = 168.978012
current_seq = 5361
count = 28
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.961411/5360, current 168.978561/5361: elapsed=17148.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.978561
last_received_ts = 168.978012
last_seq = 5361
current_ts = 168.995697
current_received_ts = 168.995163
current_seq = 5362
count = 29
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.978561/5361, current 168.995697/5362: elapsed=17138.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 168.995697
last_received_ts = 168.995163
last_seq = 5362
current_ts = 169.012848
current_received_ts = 169.012314
current_seq = 5363
count = 30
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 168.995697/5362, current 169.012848/5363: elapsed=17149.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.012848
last_received_ts = 169.012314
last_seq = 5363
current_ts = 169.029999
current_received_ts = 169.029449
current_seq = 5364
count = 31
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.012848/5363, current 169.029999/5364: elapsed=17143.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.029999
last_received_ts = 169.029449
last_seq = 5364
current_ts = 169.047150
current_received_ts = 169.046616
current_seq = 5365
count = 32
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.029999/5364, current 169.047150/5365: elapsed=17153.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.047150
last_received_ts = 169.046616
last_seq = 5365
current_ts = 169.064301
current_received_ts = 169.063751
current_seq = 5366
count = 33
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.047150/5365, current 169.064301/5366: elapsed=17153.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.064301
last_received_ts = 169.063751
last_seq = 5366
current_ts = 169.081451
current_received_ts = 169.080887
current_seq = 5367
count = 34
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.064301/5366, current 169.081451/5367: elapsed=17146.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.081451
last_received_ts = 169.080887
last_seq = 5367
current_ts = 169.098587
current_received_ts = 169.098053
current_seq = 5368
count = 35
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.081451/5367, current 169.098587/5368: elapsed=17133.0us expected=17212.7us +- 86.1us, error 0.5%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.098587
last_received_ts = 169.098053
last_seq = 5368
current_ts = 169.115738
current_received_ts = 169.115189
current_seq = 5369
count = 36
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.098587/5368, current 169.115738/5369: elapsed=17152.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.115738
last_received_ts = 169.115189
last_seq = 5369
current_ts = 169.132889
current_received_ts = 169.132355
current_seq = 5370
count = 37
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.115738/5369, current 169.132889/5370: elapsed=17151.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.132889
last_received_ts = 169.132355
last_seq = 5370
current_ts = 169.150024
current_received_ts = 169.149490
current_seq = 5371
count = 38
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.132889/5370, current 169.150024/5371: elapsed=17141.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.150024
last_received_ts = 169.149490
last_seq = 5371
current_ts = 169.167175
current_received_ts = 169.166626
current_seq = 5372
count = 39
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.150024/5371, current 169.167175/5372: elapsed=17153.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.167175
last_received_ts = 169.166626
last_seq = 5372
current_ts = 169.184311
current_received_ts = 169.183777
current_seq = 5373
count = 40
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.167175/5372, current 169.184311/5373: elapsed=17133.0us expected=17212.7us +- 86.1us, error 0.5%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.184311
last_received_ts = 169.183777
last_seq = 5373
current_ts = 169.201462
current_received_ts = 169.200928
current_seq = 5374
count = 41
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.184311/5373, current 169.201462/5374: elapsed=17153.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.201462
last_received_ts = 169.200928
last_seq = 5374
current_ts = 169.218613
current_received_ts = 169.218079
current_seq = 5375
count = 42
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.201462/5374, current 169.218613/5375: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.218613
last_received_ts = 169.218079
last_seq = 5375
current_ts = 169.235764
current_received_ts = 169.235214
current_seq = 5376
count = 43
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.218613/5375, current 169.235764/5376: elapsed=17152.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.235764
last_received_ts = 169.235214
last_seq = 5376
current_ts = 169.252914
current_received_ts = 169.252350
current_seq = 5377
count = 44
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.235764/5376, current 169.252914/5377: elapsed=17146.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.252914
last_received_ts = 169.252350
last_seq = 5377
current_ts = 169.270035
current_received_ts = 169.269501
current_seq = 5378
count = 45
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.252914/5377, current 169.270035/5378: elapsed=17133.0us expected=17212.7us +- 86.1us, error 0.5%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.270035
last_received_ts = 169.269501
last_seq = 5378
current_ts = 169.287201
current_received_ts = 169.286667
current_seq = 5379
count = 46
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.270035/5378, current 169.287201/5379: elapsed=17153.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.287201
last_received_ts = 169.286667
last_seq = 5379
current_ts = 169.304337
current_received_ts = 169.303802
current_seq = 5380
count = 47
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.287201/5379, current 169.304337/5380: elapsed=17142.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.304337
last_received_ts = 169.303802
last_seq = 5380
current_ts = 169.321487
current_received_ts = 169.320938
current_seq = 5381
count = 48
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.304337/5380, current 169.321487/5381: elapsed=17156.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.321487
last_received_ts = 169.320938
last_seq = 5381
current_ts = 169.338623
current_received_ts = 169.338089
current_seq = 5382
count = 49
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.321487/5381, current 169.338623/5382: elapsed=17136.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.338623
last_received_ts = 169.338089
last_seq = 5382
current_ts = 169.355774
current_received_ts = 169.355240
current_seq = 5383
count = 50
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.338623/5382, current 169.355774/5383: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.355774
last_received_ts = 169.355240
last_seq = 5383
current_ts = 169.372925
current_received_ts = 169.372375
current_seq = 5384
count = 51
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.355774/5383, current 169.372925/5384: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.372925
last_received_ts = 169.372375
last_seq = 5384
current_ts = 169.390076
current_received_ts = 169.389526
current_seq = 5385
count = 52
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.372925/5384, current 169.390076/5385: elapsed=17157.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.390076
last_received_ts = 169.389526
last_seq = 5385
current_ts = 169.407211
current_received_ts = 169.406677
current_seq = 5386
count = 53
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.390076/5385, current 169.407211/5386: elapsed=17132.0us expected=17212.7us +- 86.1us, error 0.5%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.407211
last_received_ts = 169.406677
last_seq = 5386
current_ts = 169.424362
current_received_ts = 169.423813
current_seq = 5387
count = 54
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.407211/5386, current 169.424362/5387: elapsed=17154.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.424362
last_received_ts = 169.423813
last_seq = 5387
current_ts = 169.441498
current_received_ts = 169.440964
current_seq = 5388
count = 55
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.424362/5387, current 169.441498/5388: elapsed=17138.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.441498
last_received_ts = 169.440964
last_seq = 5388
current_ts = 169.458664
current_received_ts = 169.458115
current_seq = 5389
count = 56
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.441498/5388, current 169.458664/5389: elapsed=17160.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.458664
last_received_ts = 169.458115
last_seq = 5389
current_ts = 169.475800
current_received_ts = 169.475266
current_seq = 5390
count = 57
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.458664/5389, current 169.475800/5390: elapsed=17138.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.475800
last_received_ts = 169.475266
last_seq = 5390
current_ts = 169.492935
current_received_ts = 169.492416
current_seq = 5391
count = 58
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.475800/5390, current 169.492935/5391: elapsed=17140.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.492935
last_received_ts = 169.492416
last_seq = 5391
current_ts = 169.510086
current_received_ts = 169.509491
current_seq = 5392
count = 59
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.492935/5391, current 169.510086/5392: elapsed=17150.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.510086
last_received_ts = 169.509491
last_seq = 5392
current_ts = 169.527237
current_received_ts = 169.526627
current_seq = 5393
count = 60
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.510086/5392, current 169.527237/5393: elapsed=17141.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.527237
last_received_ts = 169.526627
last_seq = 5393
current_ts = 169.544388
current_received_ts = 169.543762
current_seq = 5394
count = 61
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.527237/5393, current 169.544388/5394: elapsed=17160.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.544388
last_received_ts = 169.543762
last_seq = 5394
current_ts = 169.561523
current_received_ts = 169.560928
current_seq = 5395
count = 62
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.544388/5394, current 169.561523/5395: elapsed=17134.0us expected=17212.7us +- 86.1us, error 0.5%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.561523
last_received_ts = 169.560928
last_seq = 5395
current_ts = 169.578674
current_received_ts = 169.578079
current_seq = 5396
count = 63
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.561523/5395, current 169.578674/5396: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.578674
last_received_ts = 169.578079
last_seq = 5396
current_ts = 169.595810
current_received_ts = 169.595215
current_seq = 5397
count = 64
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.578674/5396, current 169.595810/5397: elapsed=17146.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.595810
last_received_ts = 169.595215
last_seq = 5397
current_ts = 169.612976
current_received_ts = 169.612442
current_seq = 5398
count = 65
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.595810/5397, current 169.612976/5398: elapsed=17160.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.612976
last_received_ts = 169.612442
last_seq = 5398
current_ts = 169.630112
current_received_ts = 169.629578
current_seq = 5399
count = 66
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.612976/5398, current 169.630112/5399: elapsed=17143.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.630112
last_received_ts = 169.629578
last_seq = 5399
current_ts = 169.647263
current_received_ts = 169.646713
current_seq = 5400
count = 67
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.630112/5399, current 169.647263/5400: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.647263
last_received_ts = 169.646713
last_seq = 5400
current_ts = 169.664398
current_received_ts = 169.663940
current_seq = 5401
count = 68
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.647263/5400, current 169.664398/5401: elapsed=17140.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.664398
last_received_ts = 169.663940
last_seq = 5401
current_ts = 169.681549
current_received_ts = 169.681015
current_seq = 5402
count = 69
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.664398/5401, current 169.681549/5402: elapsed=17148.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.681549
last_received_ts = 169.681015
last_seq = 5402
current_ts = 169.698700
current_received_ts = 169.698105
current_seq = 5403
count = 70
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.681549/5402, current 169.698700/5403: elapsed=17142.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.698700
last_received_ts = 169.698105
last_seq = 5403
current_ts = 169.715836
current_received_ts = 169.715240
current_seq = 5404
count = 71
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.698700/5403, current 169.715836/5404: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.715836
last_received_ts = 169.715240
last_seq = 5404
current_ts = 169.732986
current_received_ts = 169.732391
current_seq = 5405
count = 72
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.715836/5404, current 169.732986/5405: elapsed=17145.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.732986
last_received_ts = 169.732391
last_seq = 5405
current_ts = 169.750137
current_received_ts = 169.749603
current_seq = 5406
count = 73
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.732986/5405, current 169.750137/5406: elapsed=17158.0us expected=17212.7us +- 86.1us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.750137
last_received_ts = 169.749603
last_seq = 5406
current_ts = 169.767288
current_received_ts = 169.766739
current_seq = 5407
count = 74
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.750137/5406, current 169.767288/5407: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.767288
last_received_ts = 169.766739
last_seq = 5407
current_ts = 169.784439
current_received_ts = 169.783890
current_seq = 5408
count = 75
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.767288/5407, current 169.784439/5408: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.784439
last_received_ts = 169.783890
last_seq = 5408
current_ts = 169.801575
current_received_ts = 169.801086
current_seq = 5409
count = 76
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.784439/5408, current 169.801575/5409: elapsed=17147.0us expected=17212.7us +- 86.1us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 169.801575
last_received_ts = 169.801086
last_seq = 5409
current_ts = 169.818695
current_received_ts = 169.818146
current_seq = 5410
count = 77
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 169.801575/5409, current 169.818695/5410: elapsed=17109.0us expected=17212.7us +- 86.1us, error 0.6%
(kms_flip:3860) DEBUG: inconsistent flip ts/seq: last 169.801575/5409, current 169.818695/5410: elapsed=17109.0us expected=17212.7us
(kms_flip:3860) DEBUG: expected 157030, counted 77, encoder type 2
(kms_flip:3860) DEBUG: dropped frames, expected 157030, counted 77, encoder type 2
(kms_flip:3860) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3860) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3860) igt_core-INFO: Stack trace:
(kms_flip:3860) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3860) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3860) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3860) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3860) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3860) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3860) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3860) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (4.897s)
Starting dynamic subtest: B-HDMI-A2
(kms_flip:3860) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3860) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3860) DEBUG: flip ts/seq: last 173.785599/3793, current 173.802536/3794: elapsed=16944.0us expected=16951.6us +- 84.8us, error 0.0%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.802536
last_received_ts = 173.802002
last_seq = 3794
current_ts = 173.819473
current_received_ts = 173.818924
current_seq = 3795
count = 24
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.802536/3794, current 173.819473/3795: elapsed=16938.0us expected=16951.6us +- 84.8us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.819473
last_received_ts = 173.818924
last_seq = 3795
current_ts = 173.836395
current_received_ts = 173.835846
current_seq = 3796
count = 25
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.819473/3795, current 173.836395/3796: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.836395
last_received_ts = 173.835846
last_seq = 3796
current_ts = 173.853317
current_received_ts = 173.852753
current_seq = 3797
count = 26
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.836395/3796, current 173.853317/3797: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.853317
last_received_ts = 173.852753
last_seq = 3797
current_ts = 173.870224
current_received_ts = 173.869675
current_seq = 3798
count = 27
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.853317/3797, current 173.870224/3798: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.870224
last_received_ts = 173.869675
last_seq = 3798
current_ts = 173.887146
current_received_ts = 173.886597
current_seq = 3799
count = 28
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.870224/3798, current 173.887146/3799: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.887146
last_received_ts = 173.886597
last_seq = 3799
current_ts = 173.904068
current_received_ts = 173.903519
current_seq = 3800
count = 29
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.887146/3799, current 173.904068/3800: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.904068
last_received_ts = 173.903519
last_seq = 3800
current_ts = 173.920990
current_received_ts = 173.920425
current_seq = 3801
count = 30
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.904068/3800, current 173.920990/3801: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.920990
last_received_ts = 173.920425
last_seq = 3801
current_ts = 173.937897
current_received_ts = 173.937347
current_seq = 3802
count = 31
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.920990/3801, current 173.937897/3802: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.937897
last_received_ts = 173.937347
last_seq = 3802
current_ts = 173.954803
current_received_ts = 173.954269
current_seq = 3803
count = 32
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.937897/3802, current 173.954803/3803: elapsed=16908.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.954803
last_received_ts = 173.954269
last_seq = 3803
current_ts = 173.971741
current_received_ts = 173.971191
current_seq = 3804
count = 33
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.954803/3803, current 173.971741/3804: elapsed=16931.0us expected=16951.6us +- 84.8us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.971741
last_received_ts = 173.971191
last_seq = 3804
current_ts = 173.988647
current_received_ts = 173.988113
current_seq = 3805
count = 34
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.971741/3804, current 173.988647/3805: elapsed=16911.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 173.988647
last_received_ts = 173.988113
last_seq = 3805
current_ts = 174.005569
current_received_ts = 174.005035
current_seq = 3806
count = 35
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 173.988647/3805, current 174.005569/3806: elapsed=16912.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.005569
last_received_ts = 174.005035
last_seq = 3806
current_ts = 174.022491
current_received_ts = 174.021927
current_seq = 3807
count = 36
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.005569/3806, current 174.022491/3807: elapsed=16925.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.022491
last_received_ts = 174.021927
last_seq = 3807
current_ts = 174.039413
current_received_ts = 174.038849
current_seq = 3808
count = 37
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.022491/3807, current 174.039413/3808: elapsed=16920.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.039413
last_received_ts = 174.038849
last_seq = 3808
current_ts = 174.056320
current_received_ts = 174.055771
current_seq = 3809
count = 38
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.039413/3808, current 174.056320/3809: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.056320
last_received_ts = 174.055771
last_seq = 3809
current_ts = 174.073242
current_received_ts = 174.072693
current_seq = 3810
count = 39
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.056320/3809, current 174.073242/3810: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.073242
last_received_ts = 174.072693
last_seq = 3810
current_ts = 174.090149
current_received_ts = 174.089600
current_seq = 3811
count = 40
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.073242/3810, current 174.090149/3811: elapsed=16913.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.090149
last_received_ts = 174.089600
last_seq = 3811
current_ts = 174.107071
current_received_ts = 174.106537
current_seq = 3812
count = 41
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.090149/3811, current 174.107071/3812: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.107071
last_received_ts = 174.106537
last_seq = 3812
current_ts = 174.123993
current_received_ts = 174.123428
current_seq = 3813
count = 42
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.107071/3812, current 174.123993/3813: elapsed=16915.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.123993
last_received_ts = 174.123428
last_seq = 3813
current_ts = 174.140900
current_received_ts = 174.140350
current_seq = 3814
count = 43
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.123993/3813, current 174.140900/3814: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.140900
last_received_ts = 174.140350
last_seq = 3814
current_ts = 174.157822
current_received_ts = 174.157272
current_seq = 3815
count = 44
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.140900/3814, current 174.157822/3815: elapsed=16920.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.157822
last_received_ts = 174.157272
last_seq = 3815
current_ts = 174.174744
current_received_ts = 174.174194
current_seq = 3816
count = 45
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.157822/3815, current 174.174744/3816: elapsed=16920.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.174744
last_received_ts = 174.174194
last_seq = 3816
current_ts = 174.191666
current_received_ts = 174.191101
current_seq = 3817
count = 46
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.174744/3816, current 174.191666/3817: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.191666
last_received_ts = 174.191101
last_seq = 3817
current_ts = 174.208572
current_received_ts = 174.208038
current_seq = 3818
count = 47
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.191666/3817, current 174.208572/3818: elapsed=16908.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.208572
last_received_ts = 174.208038
last_seq = 3818
current_ts = 174.225494
current_received_ts = 174.224945
current_seq = 3819
count = 48
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.208572/3818, current 174.225494/3819: elapsed=16924.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.225494
last_received_ts = 174.224945
last_seq = 3819
current_ts = 174.242401
current_received_ts = 174.241867
current_seq = 3820
count = 49
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.225494/3819, current 174.242401/3820: elapsed=16908.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.242401
last_received_ts = 174.241867
last_seq = 3820
current_ts = 174.259323
current_received_ts = 174.258774
current_seq = 3821
count = 50
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.242401/3820, current 174.259323/3821: elapsed=16925.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.259323
last_received_ts = 174.258774
last_seq = 3821
current_ts = 174.276245
current_received_ts = 174.275681
current_seq = 3822
count = 51
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.259323/3821, current 174.276245/3822: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.276245
last_received_ts = 174.275681
last_seq = 3822
current_ts = 174.293152
current_received_ts = 174.292603
current_seq = 3823
count = 52
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.276245/3822, current 174.293152/3823: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.293152
last_received_ts = 174.292603
last_seq = 3823
current_ts = 174.310074
current_received_ts = 174.309525
current_seq = 3824
count = 53
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.293152/3823, current 174.310074/3824: elapsed=16919.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.310074
last_received_ts = 174.309525
last_seq = 3824
current_ts = 174.326996
current_received_ts = 174.326447
current_seq = 3825
count = 54
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.310074/3824, current 174.326996/3825: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.326996
last_received_ts = 174.326447
last_seq = 3825
current_ts = 174.343903
current_received_ts = 174.343353
current_seq = 3826
count = 55
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.326996/3825, current 174.343903/3826: elapsed=16914.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.343903
last_received_ts = 174.343353
last_seq = 3826
current_ts = 174.360825
current_received_ts = 174.360291
current_seq = 3827
count = 56
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.343903/3826, current 174.360825/3827: elapsed=16919.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.360825
last_received_ts = 174.360291
last_seq = 3827
current_ts = 174.377747
current_received_ts = 174.377197
current_seq = 3828
count = 57
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.360825/3827, current 174.377747/3828: elapsed=16913.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.377747
last_received_ts = 174.377197
last_seq = 3828
current_ts = 174.394669
current_received_ts = 174.394119
current_seq = 3829
count = 58
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.377747/3828, current 174.394669/3829: elapsed=16920.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.394669
last_received_ts = 174.394119
last_seq = 3829
current_ts = 174.411575
current_received_ts = 174.411041
current_seq = 3830
count = 59
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.394669/3829, current 174.411575/3830: elapsed=16914.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.411575
last_received_ts = 174.411041
last_seq = 3830
current_ts = 174.428482
current_received_ts = 174.427948
current_seq = 3831
count = 60
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.411575/3830, current 174.428482/3831: elapsed=16912.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.428482
last_received_ts = 174.427948
last_seq = 3831
current_ts = 174.445419
current_received_ts = 174.444962
current_seq = 3832
count = 61
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.428482/3831, current 174.445419/3832: elapsed=16927.0us expected=16951.6us +- 84.8us, error 0.1%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.445419
last_received_ts = 174.444962
last_seq = 3832
current_ts = 174.462341
current_received_ts = 174.461929
current_seq = 3833
count = 62
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.445419/3832, current 174.462341/3833: elapsed=16919.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.462341
last_received_ts = 174.461929
last_seq = 3833
current_ts = 174.479248
current_received_ts = 174.478760
current_seq = 3834
count = 63
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.462341/3833, current 174.479248/3834: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.479248
last_received_ts = 174.478760
last_seq = 3834
current_ts = 174.496170
current_received_ts = 174.495636
current_seq = 3835
count = 64
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.479248/3834, current 174.496170/3835: elapsed=16915.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.496170
last_received_ts = 174.495636
last_seq = 3835
current_ts = 174.513077
current_received_ts = 174.512497
current_seq = 3836
count = 65
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.496170/3835, current 174.513077/3836: elapsed=16914.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.513077
last_received_ts = 174.512497
last_seq = 3836
current_ts = 174.529999
current_received_ts = 174.529388
current_seq = 3837
count = 66
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.513077/3836, current 174.529999/3837: elapsed=16924.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.529999
last_received_ts = 174.529388
last_seq = 3837
current_ts = 174.546921
current_received_ts = 174.546280
current_seq = 3838
count = 67
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.529999/3837, current 174.546921/3838: elapsed=16914.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.546921
last_received_ts = 174.546280
last_seq = 3838
current_ts = 174.563828
current_received_ts = 174.563232
current_seq = 3839
count = 68
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.546921/3838, current 174.563828/3839: elapsed=16907.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.563828
last_received_ts = 174.563232
last_seq = 3839
current_ts = 174.580734
current_received_ts = 174.580139
current_seq = 3840
count = 69
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.563828/3839, current 174.580734/3840: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.580734
last_received_ts = 174.580139
last_seq = 3840
current_ts = 174.597656
current_received_ts = 174.597076
current_seq = 3841
count = 70
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.580734/3840, current 174.597656/3841: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.597656
last_received_ts = 174.597076
last_seq = 3841
current_ts = 174.614578
current_received_ts = 174.613968
current_seq = 3842
count = 71
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.597656/3841, current 174.614578/3842: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.614578
last_received_ts = 174.613968
last_seq = 3842
current_ts = 174.631500
current_received_ts = 174.630890
current_seq = 3843
count = 72
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.614578/3842, current 174.631500/3843: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.631500
last_received_ts = 174.630890
last_seq = 3843
current_ts = 174.648407
current_received_ts = 174.647812
current_seq = 3844
count = 73
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.631500/3843, current 174.648407/3844: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.648407
last_received_ts = 174.647812
last_seq = 3844
current_ts = 174.665329
current_received_ts = 174.664734
current_seq = 3845
count = 74
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.648407/3844, current 174.665329/3845: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.665329
last_received_ts = 174.664734
last_seq = 3845
current_ts = 174.682251
current_received_ts = 174.681641
current_seq = 3846
count = 75
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.665329/3845, current 174.682251/3846: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.682251
last_received_ts = 174.681641
last_seq = 3846
current_ts = 174.699158
current_received_ts = 174.698563
current_seq = 3847
count = 76
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.682251/3846, current 174.699158/3847: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.699158
last_received_ts = 174.698563
last_seq = 3847
current_ts = 174.716080
current_received_ts = 174.715485
current_seq = 3848
count = 77
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.699158/3847, current 174.716080/3848: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.716080
last_received_ts = 174.715485
last_seq = 3848
current_ts = 174.733002
current_received_ts = 174.732391
current_seq = 3849
count = 78
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.716080/3848, current 174.733002/3849: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.733002
last_received_ts = 174.732391
last_seq = 3849
current_ts = 174.749908
current_received_ts = 174.749313
current_seq = 3850
count = 79
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.733002/3849, current 174.749908/3850: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.749908
last_received_ts = 174.749313
last_seq = 3850
current_ts = 174.766830
current_received_ts = 174.766235
current_seq = 3851
count = 80
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.749908/3850, current 174.766830/3851: elapsed=16918.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.766830
last_received_ts = 174.766235
last_seq = 3851
current_ts = 174.783752
current_received_ts = 174.783142
current_seq = 3852
count = 81
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.766830/3851, current 174.783752/3852: elapsed=16916.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.783752
last_received_ts = 174.783142
last_seq = 3852
current_ts = 174.800659
current_received_ts = 174.800064
current_seq = 3853
count = 82
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.783752/3852, current 174.800659/3853: elapsed=16917.0us expected=16951.6us +- 84.8us, error 0.2%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.800659
last_received_ts = 174.800064
last_seq = 3853
current_ts = 174.817566
current_received_ts = 174.816971
current_seq = 3854
count = 83
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.800659/3853, current 174.817566/3854: elapsed=16906.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.817566
last_received_ts = 174.816971
last_seq = 3854
current_ts = 174.834457
current_received_ts = 174.833847
current_seq = 3855
count = 84
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.817566/3854, current 174.834457/3855: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.834457
last_received_ts = 174.833847
last_seq = 3855
current_ts = 174.851349
current_received_ts = 174.850739
current_seq = 3856
count = 85
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.834457/3855, current 174.851349/3856: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.851349
last_received_ts = 174.850739
last_seq = 3856
current_ts = 174.868225
current_received_ts = 174.867630
current_seq = 3857
count = 86
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.851349/3856, current 174.868225/3857: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.868225
last_received_ts = 174.867630
last_seq = 3857
current_ts = 174.885117
current_received_ts = 174.884521
current_seq = 3858
count = 87
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.868225/3857, current 174.885117/3858: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.885117
last_received_ts = 174.884521
last_seq = 3858
current_ts = 174.902008
current_received_ts = 174.901398
current_seq = 3859
count = 88
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.885117/3858, current 174.902008/3859: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.902008
last_received_ts = 174.901398
last_seq = 3859
current_ts = 174.918884
current_received_ts = 174.918289
current_seq = 3860
count = 89
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.902008/3859, current 174.918884/3860: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.918884
last_received_ts = 174.918289
last_seq = 3860
current_ts = 174.935776
current_received_ts = 174.935181
current_seq = 3861
count = 90
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.918884/3860, current 174.935776/3861: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.935776
last_received_ts = 174.935181
last_seq = 3861
current_ts = 174.952667
current_received_ts = 174.952057
current_seq = 3862
count = 91
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.935776/3861, current 174.952667/3862: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.952667
last_received_ts = 174.952057
last_seq = 3862
current_ts = 174.969559
current_received_ts = 174.968948
current_seq = 3863
count = 92
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.952667/3862, current 174.969559/3863: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.969559
last_received_ts = 174.968948
last_seq = 3863
current_ts = 174.986435
current_received_ts = 174.985840
current_seq = 3864
count = 93
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.969559/3863, current 174.986435/3864: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 174.986435
last_received_ts = 174.985840
last_seq = 3864
current_ts = 175.003326
current_received_ts = 175.002716
current_seq = 3865
count = 94
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 174.986435/3864, current 175.003326/3865: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.003326
last_received_ts = 175.002716
last_seq = 3865
current_ts = 175.020218
current_received_ts = 175.019608
current_seq = 3866
count = 95
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.003326/3865, current 175.020218/3866: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.020218
last_received_ts = 175.019608
last_seq = 3866
current_ts = 175.037094
current_received_ts = 175.036499
current_seq = 3867
count = 96
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.020218/3866, current 175.037094/3867: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.037094
last_received_ts = 175.036499
last_seq = 3867
current_ts = 175.053986
current_received_ts = 175.053391
current_seq = 3868
count = 97
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.037094/3867, current 175.053986/3868: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.053986
last_received_ts = 175.053391
last_seq = 3868
current_ts = 175.070877
current_received_ts = 175.070267
current_seq = 3869
count = 98
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.053986/3868, current 175.070877/3869: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.070877
last_received_ts = 175.070267
last_seq = 3869
current_ts = 175.087753
current_received_ts = 175.087158
current_seq = 3870
count = 99
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.070877/3869, current 175.087753/3870: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.087753
last_received_ts = 175.087158
last_seq = 3870
current_ts = 175.104645
current_received_ts = 175.104065
current_seq = 3871
count = 100
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.087753/3870, current 175.104645/3871: elapsed=16891.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.104645
last_received_ts = 175.104065
last_seq = 3871
current_ts = 175.121536
current_received_ts = 175.120941
current_seq = 3872
count = 101
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.104645/3871, current 175.121536/3872: elapsed=16885.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.121536
last_received_ts = 175.120941
last_seq = 3872
current_ts = 175.138428
current_received_ts = 175.137817
current_seq = 3873
count = 102
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.121536/3872, current 175.138428/3873: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.138428
last_received_ts = 175.137817
last_seq = 3873
current_ts = 175.155304
current_received_ts = 175.154709
current_seq = 3874
count = 103
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.138428/3873, current 175.155304/3874: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.155304
last_received_ts = 175.154709
last_seq = 3874
current_ts = 175.172195
current_received_ts = 175.171600
current_seq = 3875
count = 104
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.155304/3874, current 175.172195/3875: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.172195
last_received_ts = 175.171600
last_seq = 3875
current_ts = 175.189087
current_received_ts = 175.188477
current_seq = 3876
count = 105
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.172195/3875, current 175.189087/3876: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.189087
last_received_ts = 175.188477
last_seq = 3876
current_ts = 175.205963
current_received_ts = 175.205368
current_seq = 3877
count = 106
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.189087/3876, current 175.205963/3877: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.205963
last_received_ts = 175.205368
last_seq = 3877
current_ts = 175.222855
current_received_ts = 175.222260
current_seq = 3878
count = 107
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.205963/3877, current 175.222855/3878: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.222855
last_received_ts = 175.222260
last_seq = 3878
current_ts = 175.239746
current_received_ts = 175.239136
current_seq = 3879
count = 108
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.222855/3878, current 175.239746/3879: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.239746
last_received_ts = 175.239136
last_seq = 3879
current_ts = 175.256638
current_received_ts = 175.256042
current_seq = 3880
count = 109
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.239746/3879, current 175.256638/3880: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.256638
last_received_ts = 175.256042
last_seq = 3880
current_ts = 175.273514
current_received_ts = 175.272919
current_seq = 3881
count = 110
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.256638/3880, current 175.273514/3881: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.273514
last_received_ts = 175.272919
last_seq = 3881
current_ts = 175.290405
current_received_ts = 175.289795
current_seq = 3882
count = 111
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.273514/3881, current 175.290405/3882: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.290405
last_received_ts = 175.289795
last_seq = 3882
current_ts = 175.307297
current_received_ts = 175.306686
current_seq = 3883
count = 112
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.290405/3882, current 175.307297/3883: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.307297
last_received_ts = 175.306686
last_seq = 3883
current_ts = 175.324173
current_received_ts = 175.323578
current_seq = 3884
count = 113
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.307297/3883, current 175.324173/3884: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.324173
last_received_ts = 175.323578
last_seq = 3884
current_ts = 175.341064
current_received_ts = 175.340469
current_seq = 3885
count = 114
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.324173/3884, current 175.341064/3885: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.341064
last_received_ts = 175.340469
last_seq = 3885
current_ts = 175.357956
current_received_ts = 175.357346
current_seq = 3886
count = 115
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.341064/3885, current 175.357956/3886: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.357956
last_received_ts = 175.357346
last_seq = 3886
current_ts = 175.374847
current_received_ts = 175.374237
current_seq = 3887
count = 116
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.357956/3886, current 175.374847/3887: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.374847
last_received_ts = 175.374237
last_seq = 3887
current_ts = 175.391724
current_received_ts = 175.391129
current_seq = 3888
count = 117
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.374847/3887, current 175.391724/3888: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.391724
last_received_ts = 175.391129
last_seq = 3888
current_ts = 175.408615
current_received_ts = 175.408005
current_seq = 3889
count = 118
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.391724/3888, current 175.408615/3889: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.408615
last_received_ts = 175.408005
last_seq = 3889
current_ts = 175.425507
current_received_ts = 175.425125
current_seq = 3890
count = 119
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.408615/3889, current 175.425507/3890: elapsed=16898.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.425507
last_received_ts = 175.425125
last_seq = 3890
current_ts = 175.442383
current_received_ts = 175.441895
current_seq = 3891
count = 120
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.425507/3890, current 175.442383/3891: elapsed=16877.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.442383
last_received_ts = 175.441895
last_seq = 3891
current_ts = 175.459290
current_received_ts = 175.458817
current_seq = 3892
count = 121
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.442383/3891, current 175.459290/3892: elapsed=16895.0us expected=16951.6us +- 84.8us, error 0.3%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.459290
last_received_ts = 175.458817
last_seq = 3892
current_ts = 175.476166
current_received_ts = 175.475632
current_seq = 3893
count = 122
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.459290/3892, current 175.476166/3893: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.476166
last_received_ts = 175.475632
last_seq = 3893
current_ts = 175.493057
current_received_ts = 175.492523
current_seq = 3894
count = 123
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.476166/3893, current 175.493057/3894: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.493057
last_received_ts = 175.492523
last_seq = 3894
current_ts = 175.509949
current_received_ts = 175.509384
current_seq = 3895
count = 124
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.493057/3894, current 175.509949/3895: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.509949
last_received_ts = 175.509384
last_seq = 3895
current_ts = 175.526825
current_received_ts = 175.526276
current_seq = 3896
count = 125
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.509949/3895, current 175.526825/3896: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.526825
last_received_ts = 175.526276
last_seq = 3896
current_ts = 175.543716
current_received_ts = 175.543167
current_seq = 3897
count = 126
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.526825/3896, current 175.543716/3897: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.543716
last_received_ts = 175.543167
last_seq = 3897
current_ts = 175.560608
current_received_ts = 175.560074
current_seq = 3898
count = 127
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.543716/3897, current 175.560608/3898: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.560608
last_received_ts = 175.560074
last_seq = 3898
current_ts = 175.577499
current_received_ts = 175.576935
current_seq = 3899
count = 128
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.560608/3898, current 175.577499/3899: elapsed=16887.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.577499
last_received_ts = 175.576935
last_seq = 3899
current_ts = 175.594376
current_received_ts = 175.593826
current_seq = 3900
count = 129
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.577499/3899, current 175.594376/3900: elapsed=16885.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.594376
last_received_ts = 175.593826
last_seq = 3900
current_ts = 175.611267
current_received_ts = 175.610718
current_seq = 3901
count = 130
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.594376/3900, current 175.611267/3901: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.611267
last_received_ts = 175.610718
last_seq = 3901
current_ts = 175.628159
current_received_ts = 175.627594
current_seq = 3902
count = 131
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.611267/3901, current 175.628159/3902: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.628159
last_received_ts = 175.627594
last_seq = 3902
current_ts = 175.645035
current_received_ts = 175.644485
current_seq = 3903
count = 132
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.628159/3902, current 175.645035/3903: elapsed=16886.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.645035
last_received_ts = 175.644485
last_seq = 3903
current_ts = 175.661926
current_received_ts = 175.661377
current_seq = 3904
count = 133
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.645035/3903, current 175.661926/3904: elapsed=16885.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.661926
last_received_ts = 175.661377
last_seq = 3904
current_ts = 175.678818
current_received_ts = 175.678268
current_seq = 3905
count = 134
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.661926/3904, current 175.678818/3905: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.678818
last_received_ts = 175.678268
last_seq = 3905
current_ts = 175.695709
current_received_ts = 175.695145
current_seq = 3906
count = 135
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.678818/3905, current 175.695709/3906: elapsed=16888.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.695709
last_received_ts = 175.695145
last_seq = 3906
current_ts = 175.712585
current_received_ts = 175.712067
current_seq = 3907
count = 136
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.695709/3906, current 175.712585/3907: elapsed=16889.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.712585
last_received_ts = 175.712067
last_seq = 3907
current_ts = 175.729477
current_received_ts = 175.728928
current_seq = 3908
count = 137
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.712585/3907, current 175.729477/3908: elapsed=16879.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.729477
last_received_ts = 175.728928
last_seq = 3908
current_ts = 175.746368
current_received_ts = 175.745804
current_seq = 3909
count = 138
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.729477/3908, current 175.746368/3909: elapsed=16892.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.746368
last_received_ts = 175.745804
last_seq = 3909
current_ts = 175.763245
current_received_ts = 175.762695
current_seq = 3910
count = 139
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.746368/3909, current 175.763245/3910: elapsed=16889.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.763245
last_received_ts = 175.762695
last_seq = 3910
current_ts = 175.780136
current_received_ts = 175.779587
current_seq = 3911
count = 140
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.763245/3910, current 175.780136/3911: elapsed=16889.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.780136
last_received_ts = 175.779587
last_seq = 3911
current_ts = 175.797028
current_received_ts = 175.796463
current_seq = 3912
count = 141
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.780136/3911, current 175.797028/3912: elapsed=16882.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.797028
last_received_ts = 175.796463
last_seq = 3912
current_ts = 175.813904
current_received_ts = 175.813354
current_seq = 3913
count = 142
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.797028/3912, current 175.813904/3913: elapsed=16883.0us expected=16951.6us +- 84.8us, error 0.4%
(kms_flip:3860) DEBUG: name = flip
last_ts = 175.813904
last_received_ts = 175.813354
last_seq = 3913
current_ts = 175.830765
current_received_ts = 175.830215
current_seq = 3914
count = 143
seq_step = 1
(kms_flip:3860) DEBUG: flip ts/seq: last 175.813904/3913, current 175.830765/3914: elapsed=16861.0us expected=16951.6us +- 84.8us, error 0.5%
(kms_flip:3860) DEBUG: inconsistent flip ts/seq: last 175.813904/3913, current 175.830765/3914: elapsed=16861.0us expected=16951.6us
(kms_flip:3860) DEBUG: expected 159449, counted 143, encoder type 2
(kms_flip:3860) DEBUG: dropped frames, expected 159449, counted 143, encoder type 2
(kms_flip:3860) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3860) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3860) igt_core-INFO: Stack trace:
(kms_flip:3860) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3860) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3860) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3860) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3860) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3860) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3860) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3860) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (6.214s)
Starting dynamic subtest: C-HDMI-A2
Dynamic subtest C-HDMI-A2: SUCCESS (4.212s)
Starting dynamic subtest: D-HDMI-A2
Dynamic subtest D-HDMI-A2: SUCCESS (4.247s)
Starting dynamic subtest: A-DP2
Dynamic subtest A-DP2: SUCCESS (4.292s)
Starting dynamic subtest: B-DP2
Dynamic subtest B-DP2: SUCCESS (4.256s)
Starting dynamic subtest: C-DP2
Dynamic subtest C-DP2: SUCCESS (4.260s)
Starting dynamic subtest: D-DP2
Dynamic subtest D-DP2: SUCCESS (4.258s)
Subtest plain-flip-ts-check: FAIL (36.660s)