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=1741456811 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 17181.4us +- 5.692us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 17181us +- 5.692us, difference 514.8us (90.4 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.923s)
Starting dynamic subtest: B-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16934.9us +- 5.864us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16935us +- 5.864us, difference 268.2us (45.7 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.227s)
Starting dynamic subtest: C-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16791.9us +- 6.859us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16792us +- 6.859us, difference 125.2us (18.3 sigma)
Dynamic subtest C-HDMI-A2: SUCCESS (4.223s)
Starting dynamic subtest: D-HDMI-A2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16740.4us +- 7.108us accuracy 0.13%
vblank interval differs from modeline! expected 16666.7us, measured 16740us +- 7.108us, difference 73.7us (10.4 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 16711.0us +- 6.460us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16711us +- 6.460us, difference 44.3us (6.9 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 16674.5us +- 6.143us accuracy 0.11%
Dynamic subtest B-DP2: SUCCESS (4.282s)
Starting dynamic subtest: C-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16675.5us +- 5.598us accuracy 0.10%
Dynamic subtest C-DP2: SUCCESS (4.255s)
Starting dynamic subtest: D-DP2
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16675.1us +- 4.171us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16675us +- 4.171us, difference 8.4us (2.0 sigma)
Dynamic subtest D-DP2: SUCCESS (4.254s)
Subtest plain-flip-ts-check: FAIL (36.729s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A2
(kms_flip:3864) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3864) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3864) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3864) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:3864) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3864) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3864) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:3864) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3864) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x607933372cd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x607933372cd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) intel_allocator_simple-DEBUG: <ial: 0x6079333b7010, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3864) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3864) DEBUG: No stale events found
(kms_flip:3864) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3864) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3864) INFO: Expected frametime: 16667us; measured 17181.4us +- 5.692us accuracy 0.10%
(kms_flip:3864) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17181us +- 5.692us, difference 514.8us (90.4 sigma)
(kms_flip:3864) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 167.580643
current_received_ts = 167.580109
current_seq = 5318
count = 0
seq_step = 1
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.580643
last_received_ts = 167.580109
last_seq = 5318
current_ts = 167.597839
current_received_ts = 167.597244
current_seq = 5319
count = 1
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.580643/5318, current 167.597839/5319: elapsed=17183.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.597839
last_received_ts = 167.597244
last_seq = 5319
current_ts = 167.615021
current_received_ts = 167.614487
current_seq = 5320
count = 2
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.597839/5319, current 167.615021/5320: elapsed=17181.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.615021
last_received_ts = 167.614487
last_seq = 5320
current_ts = 167.632187
current_received_ts = 167.631668
current_seq = 5321
count = 3
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.615021/5320, current 167.632187/5321: elapsed=17177.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.632187
last_received_ts = 167.631668
last_seq = 5321
current_ts = 167.649384
current_received_ts = 167.648834
current_seq = 5322
count = 4
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.632187/5321, current 167.649384/5322: elapsed=17193.0us expected=17181.4us +- 85.9us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.649384
last_received_ts = 167.648834
last_seq = 5322
current_ts = 167.666565
current_received_ts = 167.666046
current_seq = 5323
count = 5
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.649384/5322, current 167.666565/5323: elapsed=17178.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.666565
last_received_ts = 167.666046
last_seq = 5323
current_ts = 167.683731
current_received_ts = 167.683182
current_seq = 5324
count = 6
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.666565/5323, current 167.683731/5324: elapsed=17175.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.683731
last_received_ts = 167.683182
last_seq = 5324
current_ts = 167.700928
current_received_ts = 167.700378
current_seq = 5325
count = 7
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.683731/5324, current 167.700928/5325: elapsed=17190.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.700928
last_received_ts = 167.700378
last_seq = 5325
current_ts = 167.718109
current_received_ts = 167.717560
current_seq = 5326
count = 8
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.700928/5325, current 167.718109/5326: elapsed=17184.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.718109
last_received_ts = 167.717560
last_seq = 5326
current_ts = 167.735275
current_received_ts = 167.734741
current_seq = 5327
count = 9
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.718109/5326, current 167.735275/5327: elapsed=17169.0us expected=17181.4us +- 85.9us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.735275
last_received_ts = 167.734741
last_seq = 5327
current_ts = 167.752472
current_received_ts = 167.751923
current_seq = 5328
count = 10
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.735275/5327, current 167.752472/5328: elapsed=17191.0us expected=17181.4us +- 85.9us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.752472
last_received_ts = 167.751923
last_seq = 5328
current_ts = 167.769653
current_received_ts = 167.769119
current_seq = 5329
count = 11
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.752472/5328, current 167.769653/5329: elapsed=17180.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.769653
last_received_ts = 167.769119
last_seq = 5329
current_ts = 167.786835
current_received_ts = 167.786285
current_seq = 5330
count = 12
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.769653/5329, current 167.786835/5330: elapsed=17182.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.786835
last_received_ts = 167.786285
last_seq = 5330
current_ts = 167.804016
current_received_ts = 167.803406
current_seq = 5331
count = 13
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.786835/5330, current 167.804016/5331: elapsed=17179.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.804016
last_received_ts = 167.803406
last_seq = 5331
current_ts = 167.821182
current_received_ts = 167.820587
current_seq = 5332
count = 14
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.804016/5331, current 167.821182/5332: elapsed=17174.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.821182
last_received_ts = 167.820587
last_seq = 5332
current_ts = 167.838364
current_received_ts = 167.837769
current_seq = 5333
count = 15
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.821182/5332, current 167.838364/5333: elapsed=17181.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.838364
last_received_ts = 167.837769
last_seq = 5333
current_ts = 167.855560
current_received_ts = 167.855026
current_seq = 5334
count = 16
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.838364/5333, current 167.855560/5334: elapsed=17189.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.855560
last_received_ts = 167.855026
last_seq = 5334
current_ts = 167.872726
current_received_ts = 167.872192
current_seq = 5335
count = 17
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.855560/5334, current 167.872726/5335: elapsed=17176.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.872726
last_received_ts = 167.872192
last_seq = 5335
current_ts = 167.889908
current_received_ts = 167.889328
current_seq = 5336
count = 18
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.872726/5335, current 167.889908/5336: elapsed=17183.0us expected=17181.4us +- 85.9us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.889908
last_received_ts = 167.889328
last_seq = 5336
current_ts = 167.907043
current_received_ts = 167.906509
current_seq = 5337
count = 19
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.889908/5336, current 167.907043/5337: elapsed=17136.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.907043
last_received_ts = 167.906509
last_seq = 5337
current_ts = 167.924179
current_received_ts = 167.923660
current_seq = 5338
count = 20
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.907043/5337, current 167.924179/5338: elapsed=17126.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.924179
last_received_ts = 167.923660
last_seq = 5338
current_ts = 167.941284
current_received_ts = 167.940781
current_seq = 5339
count = 21
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.924179/5338, current 167.941284/5339: elapsed=17112.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.941284
last_received_ts = 167.940781
last_seq = 5339
current_ts = 167.958420
current_received_ts = 167.957901
current_seq = 5340
count = 22
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.941284/5339, current 167.958420/5340: elapsed=17125.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.958420
last_received_ts = 167.957901
last_seq = 5340
current_ts = 167.975525
current_received_ts = 167.975021
current_seq = 5341
count = 23
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.958420/5340, current 167.975525/5341: elapsed=17116.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.975525
last_received_ts = 167.975021
last_seq = 5341
current_ts = 167.992645
current_received_ts = 167.992126
current_seq = 5342
count = 24
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.975525/5341, current 167.992645/5342: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 167.992645
last_received_ts = 167.992126
last_seq = 5342
current_ts = 168.009766
current_received_ts = 168.009247
current_seq = 5343
count = 25
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 167.992645/5342, current 168.009766/5343: elapsed=17122.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.009766
last_received_ts = 168.009247
last_seq = 5343
current_ts = 168.026886
current_received_ts = 168.026337
current_seq = 5344
count = 26
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.009766/5343, current 168.026886/5344: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.026886
last_received_ts = 168.026337
last_seq = 5344
current_ts = 168.044006
current_received_ts = 168.043549
current_seq = 5345
count = 27
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.026886/5344, current 168.044006/5345: elapsed=17113.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.044006
last_received_ts = 168.043549
last_seq = 5345
current_ts = 168.061127
current_received_ts = 168.060654
current_seq = 5346
count = 28
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.044006/5345, current 168.061127/5346: elapsed=17122.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.061127
last_received_ts = 168.060654
last_seq = 5346
current_ts = 168.078232
current_received_ts = 168.077759
current_seq = 5347
count = 29
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.061127/5346, current 168.078232/5347: elapsed=17114.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.078232
last_received_ts = 168.077759
last_seq = 5347
current_ts = 168.095352
current_received_ts = 168.094864
current_seq = 5348
count = 30
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.078232/5347, current 168.095352/5348: elapsed=17113.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.095352
last_received_ts = 168.094864
last_seq = 5348
current_ts = 168.112473
current_received_ts = 168.112076
current_seq = 5349
count = 31
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.095352/5348, current 168.112473/5349: elapsed=17126.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.112473
last_received_ts = 168.112076
last_seq = 5349
current_ts = 168.129593
current_received_ts = 168.129105
current_seq = 5350
count = 32
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.112473/5349, current 168.129593/5350: elapsed=17120.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.129593
last_received_ts = 168.129105
last_seq = 5350
current_ts = 168.146713
current_received_ts = 168.146210
current_seq = 5351
count = 33
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.129593/5350, current 168.146713/5351: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.146713
last_received_ts = 168.146210
last_seq = 5351
current_ts = 168.163834
current_received_ts = 168.163300
current_seq = 5352
count = 34
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.146713/5351, current 168.163834/5352: elapsed=17112.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.163834
last_received_ts = 168.163300
last_seq = 5352
current_ts = 168.180954
current_received_ts = 168.180405
current_seq = 5353
count = 35
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.163834/5352, current 168.180954/5353: elapsed=17125.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.180954
last_received_ts = 168.180405
last_seq = 5353
current_ts = 168.198074
current_received_ts = 168.197525
current_seq = 5354
count = 36
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.180954/5353, current 168.198074/5354: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.198074
last_received_ts = 168.197525
last_seq = 5354
current_ts = 168.215179
current_received_ts = 168.214645
current_seq = 5355
count = 37
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.198074/5354, current 168.215179/5355: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.215179
last_received_ts = 168.214645
last_seq = 5355
current_ts = 168.232300
current_received_ts = 168.231750
current_seq = 5356
count = 38
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.215179/5355, current 168.232300/5356: elapsed=17120.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.232300
last_received_ts = 168.231750
last_seq = 5356
current_ts = 168.249420
current_received_ts = 168.248871
current_seq = 5357
count = 39
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.232300/5356, current 168.249420/5357: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.249420
last_received_ts = 168.248871
last_seq = 5357
current_ts = 168.266541
current_received_ts = 168.265991
current_seq = 5358
count = 40
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.249420/5357, current 168.266541/5358: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.266541
last_received_ts = 168.265991
last_seq = 5358
current_ts = 168.283661
current_received_ts = 168.283112
current_seq = 5359
count = 41
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.266541/5358, current 168.283661/5359: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.283661
last_received_ts = 168.283112
last_seq = 5359
current_ts = 168.300781
current_received_ts = 168.300232
current_seq = 5360
count = 42
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.283661/5359, current 168.300781/5360: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.300781
last_received_ts = 168.300232
last_seq = 5360
current_ts = 168.317902
current_received_ts = 168.317352
current_seq = 5361
count = 43
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.300781/5360, current 168.317902/5361: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.317902
last_received_ts = 168.317352
last_seq = 5361
current_ts = 168.335022
current_received_ts = 168.334457
current_seq = 5362
count = 44
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.317902/5361, current 168.335022/5362: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.335022
last_received_ts = 168.334457
last_seq = 5362
current_ts = 168.352142
current_received_ts = 168.351669
current_seq = 5363
count = 45
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.335022/5362, current 168.352142/5363: elapsed=17120.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.352142
last_received_ts = 168.351669
last_seq = 5363
current_ts = 168.369247
current_received_ts = 168.368698
current_seq = 5364
count = 46
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.352142/5363, current 168.369247/5364: elapsed=17116.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.369247
last_received_ts = 168.368698
last_seq = 5364
current_ts = 168.386368
current_received_ts = 168.385834
current_seq = 5365
count = 47
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.369247/5364, current 168.386368/5365: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.386368
last_received_ts = 168.385834
last_seq = 5365
current_ts = 168.403488
current_received_ts = 168.402954
current_seq = 5366
count = 48
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.386368/5365, current 168.403488/5366: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.403488
last_received_ts = 168.402954
last_seq = 5366
current_ts = 168.420593
current_received_ts = 168.420074
current_seq = 5367
count = 49
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.403488/5366, current 168.420593/5367: elapsed=17112.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.420593
last_received_ts = 168.420074
last_seq = 5367
current_ts = 168.437729
current_received_ts = 168.437180
current_seq = 5368
count = 50
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.420593/5367, current 168.437729/5368: elapsed=17130.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.437729
last_received_ts = 168.437180
last_seq = 5368
current_ts = 168.454834
current_received_ts = 168.454300
current_seq = 5369
count = 51
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.437729/5368, current 168.454834/5369: elapsed=17111.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.454834
last_received_ts = 168.454300
last_seq = 5369
current_ts = 168.471954
current_received_ts = 168.471420
current_seq = 5370
count = 52
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.454834/5369, current 168.471954/5370: elapsed=17113.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.471954
last_received_ts = 168.471420
last_seq = 5370
current_ts = 168.489075
current_received_ts = 168.488541
current_seq = 5371
count = 53
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.471954/5370, current 168.489075/5371: elapsed=17123.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.489075
last_received_ts = 168.488541
last_seq = 5371
current_ts = 168.506210
current_received_ts = 168.505722
current_seq = 5372
count = 54
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.489075/5371, current 168.506210/5372: elapsed=17127.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.506210
last_received_ts = 168.505722
last_seq = 5372
current_ts = 168.523315
current_received_ts = 168.522903
current_seq = 5373
count = 55
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.506210/5372, current 168.523315/5373: elapsed=17107.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.523315
last_received_ts = 168.522903
last_seq = 5373
current_ts = 168.540436
current_received_ts = 168.539902
current_seq = 5374
count = 56
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.523315/5373, current 168.540436/5374: elapsed=17121.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.540436
last_received_ts = 168.539902
last_seq = 5374
current_ts = 168.557541
current_received_ts = 168.556961
current_seq = 5375
count = 57
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.540436/5374, current 168.557541/5375: elapsed=17113.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.557541
last_received_ts = 168.556961
last_seq = 5375
current_ts = 168.574661
current_received_ts = 168.574081
current_seq = 5376
count = 58
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.557541/5375, current 168.574661/5376: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.574661
last_received_ts = 168.574081
last_seq = 5376
current_ts = 168.591782
current_received_ts = 168.591187
current_seq = 5377
count = 59
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.574661/5376, current 168.591782/5377: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.591782
last_received_ts = 168.591187
last_seq = 5377
current_ts = 168.608902
current_received_ts = 168.608307
current_seq = 5378
count = 60
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.591782/5377, current 168.608902/5378: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.608902
last_received_ts = 168.608307
last_seq = 5378
current_ts = 168.626022
current_received_ts = 168.625427
current_seq = 5379
count = 61
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.608902/5378, current 168.626022/5379: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.626022
last_received_ts = 168.625427
last_seq = 5379
current_ts = 168.643127
current_received_ts = 168.642532
current_seq = 5380
count = 62
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.626022/5379, current 168.643127/5380: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.643127
last_received_ts = 168.642532
last_seq = 5380
current_ts = 168.660248
current_received_ts = 168.659653
current_seq = 5381
count = 63
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.643127/5380, current 168.660248/5381: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.660248
last_received_ts = 168.659653
last_seq = 5381
current_ts = 168.677368
current_received_ts = 168.676773
current_seq = 5382
count = 64
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.660248/5381, current 168.677368/5382: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.677368
last_received_ts = 168.676773
last_seq = 5382
current_ts = 168.694489
current_received_ts = 168.693893
current_seq = 5383
count = 65
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.677368/5382, current 168.694489/5383: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.694489
last_received_ts = 168.693893
last_seq = 5383
current_ts = 168.711609
current_received_ts = 168.711014
current_seq = 5384
count = 66
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.694489/5383, current 168.711609/5384: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.711609
last_received_ts = 168.711014
last_seq = 5384
current_ts = 168.728729
current_received_ts = 168.728134
current_seq = 5385
count = 67
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.711609/5384, current 168.728729/5385: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.728729
last_received_ts = 168.728134
last_seq = 5385
current_ts = 168.745850
current_received_ts = 168.745239
current_seq = 5386
count = 68
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.728729/5385, current 168.745850/5386: elapsed=17118.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.745850
last_received_ts = 168.745239
last_seq = 5386
current_ts = 168.762970
current_received_ts = 168.762360
current_seq = 5387
count = 69
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.745850/5386, current 168.762970/5387: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.762970
last_received_ts = 168.762360
last_seq = 5387
current_ts = 168.780090
current_received_ts = 168.779480
current_seq = 5388
count = 70
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.762970/5387, current 168.780090/5388: elapsed=17119.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.780090
last_received_ts = 168.779480
last_seq = 5388
current_ts = 168.797211
current_received_ts = 168.796753
current_seq = 5389
count = 71
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.780090/5388, current 168.797211/5389: elapsed=17130.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.797211
last_received_ts = 168.796753
last_seq = 5389
current_ts = 168.814331
current_received_ts = 168.813797
current_seq = 5390
count = 72
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.797211/5389, current 168.814331/5390: elapsed=17116.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.814331
last_received_ts = 168.813797
last_seq = 5390
current_ts = 168.831451
current_received_ts = 168.830994
current_seq = 5391
count = 73
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.814331/5390, current 168.831451/5391: elapsed=17115.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.831451
last_received_ts = 168.830994
last_seq = 5391
current_ts = 168.848572
current_received_ts = 168.848083
current_seq = 5392
count = 74
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.831451/5391, current 168.848572/5392: elapsed=17122.0us expected=17181.4us +- 85.9us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.848572
last_received_ts = 168.848083
last_seq = 5392
current_ts = 168.865677
current_received_ts = 168.865158
current_seq = 5393
count = 75
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.848572/5392, current 168.865677/5393: elapsed=17113.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.865677
last_received_ts = 168.865158
last_seq = 5393
current_ts = 168.882797
current_received_ts = 168.882370
current_seq = 5394
count = 76
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.865677/5393, current 168.882797/5394: elapsed=17115.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.882797
last_received_ts = 168.882370
last_seq = 5394
current_ts = 168.899918
current_received_ts = 168.899475
current_seq = 5395
count = 77
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.882797/5394, current 168.899918/5395: elapsed=17117.0us expected=17181.4us +- 85.9us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 168.899918
last_received_ts = 168.899475
last_seq = 5395
current_ts = 168.916962
current_received_ts = 168.916534
current_seq = 5396
count = 78
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 168.899918/5395, current 168.916962/5396: elapsed=17055.0us expected=17181.4us +- 85.9us, error 0.7%
(kms_flip:3864) DEBUG: inconsistent flip ts/seq: last 168.899918/5395, current 168.916962/5396: elapsed=17055.0us expected=17181.4us
(kms_flip:3864) DEBUG: expected 245196, counted 78, encoder type 2
(kms_flip:3864) DEBUG: dropped frames, expected 245196, counted 78, encoder type 2
(kms_flip:3864) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3864) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3864) igt_core-INFO: Stack trace:
(kms_flip:3864) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3864) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3864) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3864) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3864) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3864) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3864) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3864) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A2: FAIL (4.923s)
Starting dynamic subtest: B-HDMI-A2
(kms_flip:3864) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3864) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A2 failed.
**** DEBUG ****
(kms_flip:3864) DEBUG: flip ts/seq: last 172.876923/3780, current 172.893845/3781: elapsed=16934.0us expected=16934.9us +- 84.7us, error 0.0%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.893845
last_received_ts = 172.893295
last_seq = 3781
current_ts = 172.910767
current_received_ts = 172.910202
current_seq = 3782
count = 24
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.893845/3781, current 172.910767/3782: elapsed=16909.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.910767
last_received_ts = 172.910202
last_seq = 3782
current_ts = 172.927658
current_received_ts = 172.927155
current_seq = 3783
count = 25
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.910767/3782, current 172.927658/3783: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.927658
last_received_ts = 172.927155
last_seq = 3783
current_ts = 172.944565
current_received_ts = 172.944046
current_seq = 3784
count = 26
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.927658/3783, current 172.944565/3784: elapsed=16893.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.944565
last_received_ts = 172.944046
last_seq = 3784
current_ts = 172.961472
current_received_ts = 172.960922
current_seq = 3785
count = 27
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.944565/3784, current 172.961472/3785: elapsed=16914.0us expected=16934.9us +- 84.7us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.961472
last_received_ts = 172.960922
last_seq = 3785
current_ts = 172.978378
current_received_ts = 172.977814
current_seq = 3786
count = 28
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.961472/3785, current 172.978378/3786: elapsed=16901.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.978378
last_received_ts = 172.977814
last_seq = 3786
current_ts = 172.995270
current_received_ts = 172.994720
current_seq = 3787
count = 29
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.978378/3786, current 172.995270/3787: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 172.995270
last_received_ts = 172.994720
last_seq = 3787
current_ts = 173.012177
current_received_ts = 173.011627
current_seq = 3788
count = 30
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 172.995270/3787, current 173.012177/3788: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.012177
last_received_ts = 173.011627
last_seq = 3788
current_ts = 173.029083
current_received_ts = 173.028534
current_seq = 3789
count = 31
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.012177/3788, current 173.029083/3789: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.029083
last_received_ts = 173.028534
last_seq = 3789
current_ts = 173.045975
current_received_ts = 173.045425
current_seq = 3790
count = 32
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.029083/3789, current 173.045975/3790: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.045975
last_received_ts = 173.045425
last_seq = 3790
current_ts = 173.062881
current_received_ts = 173.062332
current_seq = 3791
count = 33
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.045975/3790, current 173.062881/3791: elapsed=16906.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.062881
last_received_ts = 173.062332
last_seq = 3791
current_ts = 173.079788
current_received_ts = 173.079239
current_seq = 3792
count = 34
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.062881/3791, current 173.079788/3792: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.079788
last_received_ts = 173.079239
last_seq = 3792
current_ts = 173.096695
current_received_ts = 173.096130
current_seq = 3793
count = 35
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.079788/3792, current 173.096695/3793: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.096695
last_received_ts = 173.096130
last_seq = 3793
current_ts = 173.113586
current_received_ts = 173.113052
current_seq = 3794
count = 36
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.096695/3793, current 173.113586/3794: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.113586
last_received_ts = 173.113052
last_seq = 3794
current_ts = 173.130493
current_received_ts = 173.129944
current_seq = 3795
count = 37
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.113586/3794, current 173.130493/3795: elapsed=16905.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.130493
last_received_ts = 173.129944
last_seq = 3795
current_ts = 173.147400
current_received_ts = 173.146851
current_seq = 3796
count = 38
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.130493/3795, current 173.147400/3796: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.147400
last_received_ts = 173.146851
last_seq = 3796
current_ts = 173.164307
current_received_ts = 173.163757
current_seq = 3797
count = 39
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.147400/3796, current 173.164307/3797: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.164307
last_received_ts = 173.163757
last_seq = 3797
current_ts = 173.181213
current_received_ts = 173.180664
current_seq = 3798
count = 40
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.164307/3797, current 173.181213/3798: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.181213
last_received_ts = 173.180664
last_seq = 3798
current_ts = 173.198105
current_received_ts = 173.197556
current_seq = 3799
count = 41
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.181213/3798, current 173.198105/3799: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.198105
last_received_ts = 173.197556
last_seq = 3799
current_ts = 173.215012
current_received_ts = 173.214462
current_seq = 3800
count = 42
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.198105/3799, current 173.215012/3800: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.215012
last_received_ts = 173.214462
last_seq = 3800
current_ts = 173.231918
current_received_ts = 173.231354
current_seq = 3801
count = 43
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.215012/3800, current 173.231918/3801: elapsed=16901.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.231918
last_received_ts = 173.231354
last_seq = 3801
current_ts = 173.248825
current_received_ts = 173.248260
current_seq = 3802
count = 44
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.231918/3801, current 173.248825/3802: elapsed=16906.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.248825
last_received_ts = 173.248260
last_seq = 3802
current_ts = 173.265717
current_received_ts = 173.265167
current_seq = 3803
count = 45
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.248825/3802, current 173.265717/3803: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.265717
last_received_ts = 173.265167
last_seq = 3803
current_ts = 173.282623
current_received_ts = 173.282074
current_seq = 3804
count = 46
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.265717/3803, current 173.282623/3804: elapsed=16895.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.282623
last_received_ts = 173.282074
last_seq = 3804
current_ts = 173.299530
current_received_ts = 173.299042
current_seq = 3805
count = 47
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.282623/3804, current 173.299530/3805: elapsed=16907.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.299530
last_received_ts = 173.299042
last_seq = 3805
current_ts = 173.316437
current_received_ts = 173.315933
current_seq = 3806
count = 48
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.299530/3805, current 173.316437/3806: elapsed=16906.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.316437
last_received_ts = 173.315933
last_seq = 3806
current_ts = 173.333328
current_received_ts = 173.332794
current_seq = 3807
count = 49
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.316437/3806, current 173.333328/3807: elapsed=16901.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.333328
last_received_ts = 173.332794
last_seq = 3807
current_ts = 173.350235
current_received_ts = 173.349686
current_seq = 3808
count = 50
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.333328/3807, current 173.350235/3808: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.350235
last_received_ts = 173.349686
last_seq = 3808
current_ts = 173.367142
current_received_ts = 173.366592
current_seq = 3809
count = 51
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.350235/3808, current 173.367142/3809: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.367142
last_received_ts = 173.366592
last_seq = 3809
current_ts = 173.384033
current_received_ts = 173.383484
current_seq = 3810
count = 52
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.367142/3809, current 173.384033/3810: elapsed=16901.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.384033
last_received_ts = 173.383484
last_seq = 3810
current_ts = 173.400940
current_received_ts = 173.400391
current_seq = 3811
count = 53
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.384033/3810, current 173.400940/3811: elapsed=16906.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.400940
last_received_ts = 173.400391
last_seq = 3811
current_ts = 173.417847
current_received_ts = 173.417297
current_seq = 3812
count = 54
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.400940/3811, current 173.417847/3812: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.417847
last_received_ts = 173.417297
last_seq = 3812
current_ts = 173.434753
current_received_ts = 173.434204
current_seq = 3813
count = 55
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.417847/3812, current 173.434753/3813: elapsed=16907.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.434753
last_received_ts = 173.434204
last_seq = 3813
current_ts = 173.451660
current_received_ts = 173.451096
current_seq = 3814
count = 56
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.434753/3813, current 173.451660/3814: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.451660
last_received_ts = 173.451096
last_seq = 3814
current_ts = 173.468552
current_received_ts = 173.468048
current_seq = 3815
count = 57
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.451660/3814, current 173.468552/3815: elapsed=16895.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.468552
last_received_ts = 173.468048
last_seq = 3815
current_ts = 173.485458
current_received_ts = 173.484909
current_seq = 3816
count = 58
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.468552/3815, current 173.485458/3816: elapsed=16909.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.485458
last_received_ts = 173.484909
last_seq = 3816
current_ts = 173.502365
current_received_ts = 173.501801
current_seq = 3817
count = 59
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.485458/3816, current 173.502365/3817: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.502365
last_received_ts = 173.501801
last_seq = 3817
current_ts = 173.519272
current_received_ts = 173.518707
current_seq = 3818
count = 60
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.502365/3817, current 173.519272/3818: elapsed=16908.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.519272
last_received_ts = 173.518707
last_seq = 3818
current_ts = 173.536163
current_received_ts = 173.535614
current_seq = 3819
count = 61
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.519272/3818, current 173.536163/3819: elapsed=16898.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.536163
last_received_ts = 173.535614
last_seq = 3819
current_ts = 173.553070
current_received_ts = 173.552567
current_seq = 3820
count = 62
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.536163/3819, current 173.553070/3820: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.553070
last_received_ts = 173.552567
last_seq = 3820
current_ts = 173.569962
current_received_ts = 173.569473
current_seq = 3821
count = 63
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.553070/3820, current 173.569962/3821: elapsed=16897.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.569962
last_received_ts = 173.569473
last_seq = 3821
current_ts = 173.586868
current_received_ts = 173.586380
current_seq = 3822
count = 64
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.569962/3821, current 173.586868/3822: elapsed=16907.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.586868
last_received_ts = 173.586380
last_seq = 3822
current_ts = 173.603790
current_received_ts = 173.603271
current_seq = 3823
count = 65
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.586868/3822, current 173.603790/3823: elapsed=16909.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.603790
last_received_ts = 173.603271
last_seq = 3823
current_ts = 173.620682
current_received_ts = 173.620132
current_seq = 3824
count = 66
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.603790/3823, current 173.620682/3824: elapsed=16897.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.620682
last_received_ts = 173.620132
last_seq = 3824
current_ts = 173.637573
current_received_ts = 173.637054
current_seq = 3825
count = 67
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.620682/3824, current 173.637573/3825: elapsed=16898.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.637573
last_received_ts = 173.637054
last_seq = 3825
current_ts = 173.654480
current_received_ts = 173.653931
current_seq = 3826
count = 68
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.637573/3825, current 173.654480/3826: elapsed=16908.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.654480
last_received_ts = 173.653931
last_seq = 3826
current_ts = 173.671387
current_received_ts = 173.670837
current_seq = 3827
count = 69
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.654480/3826, current 173.671387/3827: elapsed=16894.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.671387
last_received_ts = 173.670837
last_seq = 3827
current_ts = 173.688293
current_received_ts = 173.687744
current_seq = 3828
count = 70
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.671387/3827, current 173.688293/3828: elapsed=16916.0us expected=16934.9us +- 84.7us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.688293
last_received_ts = 173.687744
last_seq = 3828
current_ts = 173.705200
current_received_ts = 173.704636
current_seq = 3829
count = 71
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.688293/3828, current 173.705200/3829: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.705200
last_received_ts = 173.704636
last_seq = 3829
current_ts = 173.722092
current_received_ts = 173.721542
current_seq = 3830
count = 72
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.705200/3829, current 173.722092/3830: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.722092
last_received_ts = 173.721542
last_seq = 3830
current_ts = 173.738998
current_received_ts = 173.738449
current_seq = 3831
count = 73
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.722092/3830, current 173.738998/3831: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.738998
last_received_ts = 173.738449
last_seq = 3831
current_ts = 173.755905
current_received_ts = 173.755356
current_seq = 3832
count = 74
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.738998/3831, current 173.755905/3832: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.755905
last_received_ts = 173.755356
last_seq = 3832
current_ts = 173.772812
current_received_ts = 173.772247
current_seq = 3833
count = 75
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.755905/3832, current 173.772812/3833: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.772812
last_received_ts = 173.772247
last_seq = 3833
current_ts = 173.789703
current_received_ts = 173.789154
current_seq = 3834
count = 76
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.772812/3833, current 173.789703/3834: elapsed=16902.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.789703
last_received_ts = 173.789154
last_seq = 3834
current_ts = 173.806610
current_received_ts = 173.806061
current_seq = 3835
count = 77
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.789703/3834, current 173.806610/3835: elapsed=16897.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.806610
last_received_ts = 173.806061
last_seq = 3835
current_ts = 173.823517
current_received_ts = 173.823013
current_seq = 3836
count = 78
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.806610/3835, current 173.823517/3836: elapsed=16910.0us expected=16934.9us +- 84.7us, error 0.1%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.823517
last_received_ts = 173.823013
last_seq = 3836
current_ts = 173.840424
current_received_ts = 173.839874
current_seq = 3837
count = 79
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.823517/3836, current 173.840424/3837: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.840424
last_received_ts = 173.839874
last_seq = 3837
current_ts = 173.857330
current_received_ts = 173.856766
current_seq = 3838
count = 80
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.840424/3837, current 173.857330/3838: elapsed=16904.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.857330
last_received_ts = 173.856766
last_seq = 3838
current_ts = 173.874222
current_received_ts = 173.873672
current_seq = 3839
count = 81
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.857330/3838, current 173.874222/3839: elapsed=16903.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.874222
last_received_ts = 173.873672
last_seq = 3839
current_ts = 173.891129
current_received_ts = 173.890579
current_seq = 3840
count = 82
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.874222/3839, current 173.891129/3840: elapsed=16900.0us expected=16934.9us +- 84.7us, error 0.2%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.891129
last_received_ts = 173.890579
last_seq = 3840
current_ts = 173.908005
current_received_ts = 173.907455
current_seq = 3841
count = 83
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.891129/3840, current 173.908005/3841: elapsed=16885.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.908005
last_received_ts = 173.907455
last_seq = 3841
current_ts = 173.924881
current_received_ts = 173.924332
current_seq = 3842
count = 84
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.908005/3841, current 173.924881/3842: elapsed=16872.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.924881
last_received_ts = 173.924332
last_seq = 3842
current_ts = 173.941757
current_received_ts = 173.941208
current_seq = 3843
count = 85
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.924881/3842, current 173.941757/3843: elapsed=16877.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.941757
last_received_ts = 173.941208
last_seq = 3843
current_ts = 173.958633
current_received_ts = 173.958130
current_seq = 3844
count = 86
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.941757/3843, current 173.958633/3844: elapsed=16868.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.958633
last_received_ts = 173.958130
last_seq = 3844
current_ts = 173.975510
current_received_ts = 173.975021
current_seq = 3845
count = 87
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.958633/3844, current 173.975510/3845: elapsed=16879.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.975510
last_received_ts = 173.975021
last_seq = 3845
current_ts = 173.992386
current_received_ts = 173.991837
current_seq = 3846
count = 88
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.975510/3845, current 173.992386/3846: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 173.992386
last_received_ts = 173.991837
last_seq = 3846
current_ts = 174.009262
current_received_ts = 174.008698
current_seq = 3847
count = 89
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 173.992386/3846, current 174.009262/3847: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.009262
last_received_ts = 174.008698
last_seq = 3847
current_ts = 174.026138
current_received_ts = 174.025589
current_seq = 3848
count = 90
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.009262/3847, current 174.026138/3848: elapsed=16876.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.026138
last_received_ts = 174.025589
last_seq = 3848
current_ts = 174.042999
current_received_ts = 174.042450
current_seq = 3849
count = 91
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.026138/3848, current 174.042999/3849: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.042999
last_received_ts = 174.042450
last_seq = 3849
current_ts = 174.059875
current_received_ts = 174.059326
current_seq = 3850
count = 92
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.042999/3849, current 174.059875/3850: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.059875
last_received_ts = 174.059326
last_seq = 3850
current_ts = 174.076752
current_received_ts = 174.076202
current_seq = 3851
count = 93
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.059875/3850, current 174.076752/3851: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.076752
last_received_ts = 174.076202
last_seq = 3851
current_ts = 174.093628
current_received_ts = 174.093094
current_seq = 3852
count = 94
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.076752/3851, current 174.093628/3852: elapsed=16867.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.093628
last_received_ts = 174.093094
last_seq = 3852
current_ts = 174.110504
current_received_ts = 174.109955
current_seq = 3853
count = 95
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.093628/3852, current 174.110504/3853: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.110504
last_received_ts = 174.109955
last_seq = 3853
current_ts = 174.127380
current_received_ts = 174.126831
current_seq = 3854
count = 96
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.110504/3853, current 174.127380/3854: elapsed=16880.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.127380
last_received_ts = 174.126831
last_seq = 3854
current_ts = 174.144257
current_received_ts = 174.143646
current_seq = 3855
count = 97
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.127380/3854, current 174.144257/3855: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.144257
last_received_ts = 174.143646
last_seq = 3855
current_ts = 174.161133
current_received_ts = 174.160568
current_seq = 3856
count = 98
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.144257/3855, current 174.161133/3856: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.161133
last_received_ts = 174.160568
last_seq = 3856
current_ts = 174.177994
current_received_ts = 174.177505
current_seq = 3857
count = 99
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.161133/3856, current 174.177994/3857: elapsed=16869.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.177994
last_received_ts = 174.177505
last_seq = 3857
current_ts = 174.194885
current_received_ts = 174.194366
current_seq = 3858
count = 100
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.177994/3857, current 174.194885/3858: elapsed=16883.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.194885
last_received_ts = 174.194366
last_seq = 3858
current_ts = 174.211746
current_received_ts = 174.211258
current_seq = 3859
count = 101
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.194885/3858, current 174.211746/3859: elapsed=16866.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.211746
last_received_ts = 174.211258
last_seq = 3859
current_ts = 174.228622
current_received_ts = 174.228119
current_seq = 3860
count = 102
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.211746/3859, current 174.228622/3860: elapsed=16881.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.228622
last_received_ts = 174.228119
last_seq = 3860
current_ts = 174.245499
current_received_ts = 174.244965
current_seq = 3861
count = 103
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.228622/3860, current 174.245499/3861: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.245499
last_received_ts = 174.244965
last_seq = 3861
current_ts = 174.262375
current_received_ts = 174.261826
current_seq = 3862
count = 104
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.245499/3861, current 174.262375/3862: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.262375
last_received_ts = 174.261826
last_seq = 3862
current_ts = 174.279251
current_received_ts = 174.278702
current_seq = 3863
count = 105
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.262375/3862, current 174.279251/3863: elapsed=16878.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.279251
last_received_ts = 174.278702
last_seq = 3863
current_ts = 174.296127
current_received_ts = 174.295578
current_seq = 3864
count = 106
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.279251/3863, current 174.296127/3864: elapsed=16869.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.296127
last_received_ts = 174.295578
last_seq = 3864
current_ts = 174.313004
current_received_ts = 174.312454
current_seq = 3865
count = 107
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.296127/3864, current 174.313004/3865: elapsed=16876.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.313004
last_received_ts = 174.312454
last_seq = 3865
current_ts = 174.329880
current_received_ts = 174.329376
current_seq = 3866
count = 108
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.313004/3865, current 174.329880/3866: elapsed=16876.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.329880
last_received_ts = 174.329376
last_seq = 3866
current_ts = 174.346741
current_received_ts = 174.346207
current_seq = 3867
count = 109
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.329880/3866, current 174.346741/3867: elapsed=16873.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.346741
last_received_ts = 174.346207
last_seq = 3867
current_ts = 174.363617
current_received_ts = 174.363068
current_seq = 3868
count = 110
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.346741/3867, current 174.363617/3868: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.363617
last_received_ts = 174.363068
last_seq = 3868
current_ts = 174.380508
current_received_ts = 174.379944
current_seq = 3869
count = 111
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.363617/3868, current 174.380508/3869: elapsed=16879.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.380508
last_received_ts = 174.379944
last_seq = 3869
current_ts = 174.397369
current_received_ts = 174.396820
current_seq = 3870
count = 112
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.380508/3869, current 174.397369/3870: elapsed=16872.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.397369
last_received_ts = 174.396820
last_seq = 3870
current_ts = 174.414246
current_received_ts = 174.413712
current_seq = 3871
count = 113
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.397369/3870, current 174.414246/3871: elapsed=16867.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.414246
last_received_ts = 174.413712
last_seq = 3871
current_ts = 174.431122
current_received_ts = 174.430618
current_seq = 3872
count = 114
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.414246/3871, current 174.431122/3872: elapsed=16881.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.431122
last_received_ts = 174.430618
last_seq = 3872
current_ts = 174.447998
current_received_ts = 174.447495
current_seq = 3873
count = 115
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.431122/3872, current 174.447998/3873: elapsed=16873.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.447998
last_received_ts = 174.447495
last_seq = 3873
current_ts = 174.464859
current_received_ts = 174.464371
current_seq = 3874
count = 116
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.447998/3873, current 174.464859/3874: elapsed=16870.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.464859
last_received_ts = 174.464371
last_seq = 3874
current_ts = 174.481735
current_received_ts = 174.481216
current_seq = 3875
count = 117
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.464859/3874, current 174.481735/3875: elapsed=16877.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.481735
last_received_ts = 174.481216
last_seq = 3875
current_ts = 174.498611
current_received_ts = 174.498062
current_seq = 3876
count = 118
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.481735/3875, current 174.498611/3876: elapsed=16878.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.498611
last_received_ts = 174.498062
last_seq = 3876
current_ts = 174.515488
current_received_ts = 174.514938
current_seq = 3877
count = 119
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.498611/3876, current 174.515488/3877: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.515488
last_received_ts = 174.514938
last_seq = 3877
current_ts = 174.532364
current_received_ts = 174.531815
current_seq = 3878
count = 120
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.515488/3877, current 174.532364/3878: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.532364
last_received_ts = 174.531815
last_seq = 3878
current_ts = 174.549240
current_received_ts = 174.548691
current_seq = 3879
count = 121
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.532364/3878, current 174.549240/3879: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.549240
last_received_ts = 174.548691
last_seq = 3879
current_ts = 174.566116
current_received_ts = 174.565567
current_seq = 3880
count = 122
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.549240/3879, current 174.566116/3880: elapsed=16873.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.566116
last_received_ts = 174.565567
last_seq = 3880
current_ts = 174.582993
current_received_ts = 174.582443
current_seq = 3881
count = 123
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.566116/3880, current 174.582993/3881: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.582993
last_received_ts = 174.582443
last_seq = 3881
current_ts = 174.599869
current_received_ts = 174.599319
current_seq = 3882
count = 124
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.582993/3881, current 174.599869/3882: elapsed=16876.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.599869
last_received_ts = 174.599319
last_seq = 3882
current_ts = 174.616730
current_received_ts = 174.616196
current_seq = 3883
count = 125
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.599869/3882, current 174.616730/3883: elapsed=16867.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.616730
last_received_ts = 174.616196
last_seq = 3883
current_ts = 174.633606
current_received_ts = 174.633072
current_seq = 3884
count = 126
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.616730/3883, current 174.633606/3884: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.633606
last_received_ts = 174.633072
last_seq = 3884
current_ts = 174.650497
current_received_ts = 174.649933
current_seq = 3885
count = 127
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.633606/3884, current 174.650497/3885: elapsed=16885.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.650497
last_received_ts = 174.649933
last_seq = 3885
current_ts = 174.667358
current_received_ts = 174.666809
current_seq = 3886
count = 128
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.650497/3885, current 174.667358/3886: elapsed=16871.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.667358
last_received_ts = 174.666809
last_seq = 3886
current_ts = 174.684235
current_received_ts = 174.683685
current_seq = 3887
count = 129
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.667358/3886, current 174.684235/3887: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.684235
last_received_ts = 174.683685
last_seq = 3887
current_ts = 174.701111
current_received_ts = 174.700562
current_seq = 3888
count = 130
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.684235/3887, current 174.701111/3888: elapsed=16873.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.701111
last_received_ts = 174.700562
last_seq = 3888
current_ts = 174.717987
current_received_ts = 174.717438
current_seq = 3889
count = 131
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.701111/3888, current 174.717987/3889: elapsed=16878.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.717987
last_received_ts = 174.717438
last_seq = 3889
current_ts = 174.734863
current_received_ts = 174.734329
current_seq = 3890
count = 132
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.717987/3889, current 174.734863/3890: elapsed=16872.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.734863
last_received_ts = 174.734329
last_seq = 3890
current_ts = 174.751740
current_received_ts = 174.751190
current_seq = 3891
count = 133
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.734863/3890, current 174.751740/3891: elapsed=16877.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.751740
last_received_ts = 174.751190
last_seq = 3891
current_ts = 174.768616
current_received_ts = 174.768051
current_seq = 3892
count = 134
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.751740/3891, current 174.768616/3892: elapsed=16873.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.768616
last_received_ts = 174.768051
last_seq = 3892
current_ts = 174.785492
current_received_ts = 174.784927
current_seq = 3893
count = 135
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.768616/3892, current 174.785492/3893: elapsed=16874.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.785492
last_received_ts = 174.784927
last_seq = 3893
current_ts = 174.802353
current_received_ts = 174.801819
current_seq = 3894
count = 136
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.785492/3893, current 174.802353/3894: elapsed=16870.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.802353
last_received_ts = 174.801819
last_seq = 3894
current_ts = 174.819244
current_received_ts = 174.818680
current_seq = 3895
count = 137
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.802353/3894, current 174.819244/3895: elapsed=16882.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.819244
last_received_ts = 174.818680
last_seq = 3895
current_ts = 174.836105
current_received_ts = 174.835556
current_seq = 3896
count = 138
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.819244/3895, current 174.836105/3896: elapsed=16872.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.836105
last_received_ts = 174.835556
last_seq = 3896
current_ts = 174.852982
current_received_ts = 174.852432
current_seq = 3897
count = 139
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.836105/3896, current 174.852982/3897: elapsed=16877.0us expected=16934.9us +- 84.7us, error 0.3%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.852982
last_received_ts = 174.852432
last_seq = 3897
current_ts = 174.869858
current_received_ts = 174.869308
current_seq = 3898
count = 140
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.852982/3897, current 174.869858/3898: elapsed=16871.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.869858
last_received_ts = 174.869308
last_seq = 3898
current_ts = 174.886734
current_received_ts = 174.886185
current_seq = 3899
count = 141
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.869858/3898, current 174.886734/3899: elapsed=16875.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.886734
last_received_ts = 174.886185
last_seq = 3899
current_ts = 174.903595
current_received_ts = 174.903061
current_seq = 3900
count = 142
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.886734/3899, current 174.903595/3900: elapsed=16869.0us expected=16934.9us +- 84.7us, error 0.4%
(kms_flip:3864) DEBUG: name = flip
last_ts = 174.903595
last_received_ts = 174.903061
last_seq = 3900
current_ts = 174.920456
current_received_ts = 174.919968
current_seq = 3901
count = 143
seq_step = 1
(kms_flip:3864) DEBUG: flip ts/seq: last 174.903595/3900, current 174.920456/3901: elapsed=16850.0us expected=16934.9us +- 84.7us, error 0.5%
(kms_flip:3864) DEBUG: inconsistent flip ts/seq: last 174.903595/3900, current 174.920456/3901: elapsed=16850.0us expected=16934.9us
(kms_flip:3864) DEBUG: expected 248766, counted 143, encoder type 2
(kms_flip:3864) DEBUG: dropped frames, expected 248766, counted 143, encoder type 2
(kms_flip:3864) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3864) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3864) igt_core-INFO: Stack trace:
(kms_flip:3864) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3864) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3864) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3864) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3864) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3864) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:3864) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:3864) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A2: FAIL (6.227s)
Starting dynamic subtest: C-HDMI-A2
Dynamic subtest C-HDMI-A2: SUCCESS (4.223s)
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.282s)
Starting dynamic subtest: C-DP2
Dynamic subtest C-DP2: SUCCESS (4.255s)
Starting dynamic subtest: D-DP2
Dynamic subtest D-DP2: SUCCESS (4.254s)
Subtest plain-flip-ts-check: FAIL (36.729s)