Results for igt@kms_flip@flip-vs-absolute-wf_vblank

shard-mtlp-7

IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc7-CI_DRM_15686-g26f5fe99791d+ x86_64)

Using IGT_SRANDOM=1731467705 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-absolute-wf_vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 10777.4us +- 4.761us accuracy 0.13%
vblank interval differs from modeline! expected 11111.1us, measured 10777us +- 4.761us, difference 333.7us (70.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (6.098s)
Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 10958.4us +- 2.872us accuracy 0.08%
vblank interval differs from modeline! expected 11111.1us, measured 10958us +- 2.872us, difference 152.8us (53.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.032s)
Starting dynamic subtest: C-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11055.1us +- 2.720us accuracy 0.07%
vblank interval differs from modeline! expected 11111.1us, measured 11055us +- 2.720us, difference 56.1us (20.6 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (12.435s)
Starting dynamic subtest: D-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11095.3us +- 2.676us accuracy 0.07%
vblank interval differs from modeline! expected 11111.1us, measured 11095us +- 2.676us, difference 15.8us (5.9 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-eDP1: FAIL (12.443s)
Subtest flip-vs-absolute-wf_vblank: FAIL (39.017s)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2234 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2930 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2386 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-absolute-wf_vblank
Starting dynamic subtest: A-eDP1
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=11520)
(kms_flip:2760) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
(kms_flip:2760) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_kms-INFO:   2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
(kms_flip:2760) DEBUG: No stale events found
(kms_flip:2760) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2760) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2760) INFO: Expected frametime: 11111us; measured 10777.4us +- 4.761us accuracy 0.13%
(kms_flip:2760) INFO: vblank interval differs from modeline! expected 11111.1us, measured 10777us +- 4.761us, difference 333.7us (70.1 sigma)
(kms_flip:2760) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 504.434509
current_received_ts = 504.434113
current_seq = 23943
count = 0
seq_step = 1
(kms_flip:2760) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 504.531494
current_received_ts = 504.531494
current_seq = 23952
count = 0
seq_step = 10
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.434509
last_received_ts = 504.434113
last_seq = 23943
current_ts = 504.542297
current_received_ts = 504.542389
current_seq = 23953
count = 1
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.434509/23943, current 504.542297/23953: elapsed=107777.0us expected=107774.4us +- 538.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 504.531494
last_received_ts = 504.531494
last_seq = 23952
current_ts = 504.639282
current_received_ts = 504.639343
current_seq = 23962
count = 1
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 504.531494/23952, current 504.639282/23962: elapsed=107776.0us expected=107774.4us +- 538.9us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.542297
last_received_ts = 504.542389
last_seq = 23953
current_ts = 504.650085
current_received_ts = 504.649872
current_seq = 23963
count = 2
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.542297/23953, current 504.650085/23963: elapsed=107788.0us expected=107774.4us +- 538.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 504.639282
last_received_ts = 504.639343
last_seq = 23962
current_ts = 504.747070
current_received_ts = 504.746979
current_seq = 23972
count = 2
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 504.639282/23962, current 504.747070/23972: elapsed=107787.0us expected=107774.4us +- 538.9us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.650085
last_received_ts = 504.649872
last_seq = 23963
current_ts = 504.757843
current_received_ts = 504.757843
current_seq = 23973
count = 3
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.650085/23963, current 504.757843/23973: elapsed=107773.0us expected=107774.4us +- 538.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 504.747070
last_received_ts = 504.746979
last_seq = 23972
current_ts = 504.854980
current_received_ts = 504.855133
current_seq = 23982
count = 3
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 504.747070/23972, current 504.854980/23982: elapsed=107917.0us expected=107774.4us +- 538.9us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.757843
last_received_ts = 504.757843
last_seq = 23973
current_ts = 504.865814
current_received_ts = 504.865906
current_seq = 23983
count = 4
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.757843/23973, current 504.865814/23983: elapsed=107964.0us expected=107774.4us +- 538.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 504.854980
last_received_ts = 504.855133
last_seq = 23982
current_ts = 504.963196
current_received_ts = 504.963104
current_seq = 23992
count = 4
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 504.854980/23982, current 504.963196/23992: elapsed=108200.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.865814
last_received_ts = 504.865906
last_seq = 23983
current_ts = 504.973999
current_received_ts = 504.974121
current_seq = 23993
count = 5
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.865814/23983, current 504.973999/23993: elapsed=108193.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 504.963196
last_received_ts = 504.963104
last_seq = 23992
current_ts = 505.071381
current_received_ts = 505.071289
current_seq = 24002
count = 5
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 504.963196/23992, current 505.071381/24002: elapsed=108192.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 504.973999
last_received_ts = 504.974121
last_seq = 23993
current_ts = 505.082214
current_received_ts = 505.081848
current_seq = 24003
count = 6
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 504.973999/23993, current 505.082214/24003: elapsed=108197.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.071381
last_received_ts = 505.071289
last_seq = 24002
current_ts = 505.179565
current_received_ts = 505.179749
current_seq = 24012
count = 6
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.071381/24002, current 505.179565/24012: elapsed=108183.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.082214
last_received_ts = 505.081848
last_seq = 24003
current_ts = 505.190399
current_received_ts = 505.190521
current_seq = 24013
count = 7
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.082214/24003, current 505.190399/24013: elapsed=108184.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.179565
last_received_ts = 505.179749
last_seq = 24012
current_ts = 505.287750
current_received_ts = 505.287903
current_seq = 24022
count = 7
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.179565/24012, current 505.287750/24022: elapsed=108193.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.190399
last_received_ts = 505.190521
last_seq = 24013
current_ts = 505.298584
current_received_ts = 505.298767
current_seq = 24023
count = 8
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.190399/24013, current 505.298584/24023: elapsed=108194.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.287750
last_received_ts = 505.287903
last_seq = 24022
current_ts = 505.395935
current_received_ts = 505.396149
current_seq = 24032
count = 8
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.287750/24022, current 505.395935/24032: elapsed=108191.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.298584
last_received_ts = 505.298767
last_seq = 24023
current_ts = 505.406769
current_received_ts = 505.406921
current_seq = 24033
count = 9
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.298584/24023, current 505.406769/24033: elapsed=108186.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.395935
last_received_ts = 505.396149
last_seq = 24032
current_ts = 505.504150
current_received_ts = 505.504303
current_seq = 24042
count = 9
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.395935/24032, current 505.504150/24042: elapsed=108191.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.406769
last_received_ts = 505.406921
last_seq = 24033
current_ts = 505.514954
current_received_ts = 505.515167
current_seq = 24043
count = 10
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.406769/24033, current 505.514954/24043: elapsed=108196.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.504150
last_received_ts = 505.504303
last_seq = 24042
current_ts = 505.612335
current_received_ts = 505.612488
current_seq = 24052
count = 10
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.504150/24042, current 505.612335/24052: elapsed=108190.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.514954
last_received_ts = 505.515167
last_seq = 24043
current_ts = 505.623169
current_received_ts = 505.623138
current_seq = 24053
count = 11
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.514954/24043, current 505.623169/24053: elapsed=108197.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.612335
last_received_ts = 505.612488
last_seq = 24052
current_ts = 505.720520
current_received_ts = 505.720673
current_seq = 24062
count = 11
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.612335/24052, current 505.720520/24062: elapsed=108194.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.623169
last_received_ts = 505.623138
last_seq = 24053
current_ts = 505.731354
current_received_ts = 505.731537
current_seq = 24063
count = 12
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.623169/24053, current 505.731354/24063: elapsed=108183.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.720520
last_received_ts = 505.720673
last_seq = 24062
current_ts = 505.828735
current_received_ts = 505.828888
current_seq = 24072
count = 12
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.720520/24062, current 505.828735/24072: elapsed=108228.0us expected=107774.4us +- 538.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 505.731354
last_received_ts = 505.731537
last_seq = 24063
current_ts = 505.839600
current_received_ts = 505.839752
current_seq = 24073
count = 13
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 505.731354/24063, current 505.839600/24073: elapsed=108265.0us expected=107774.4us +- 538.9us, error 0.5%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 505.828735
last_received_ts = 505.828888
last_seq = 24072
current_ts = 505.937286
current_received_ts = 505.937439
current_seq = 24082
count = 13
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 505.828735/24072, current 505.937286/24082: elapsed=108548.0us expected=107774.4us +- 538.9us, error 0.7%
(kms_flip:2760) DEBUG: inconsistent vblank ts/seq: last 505.828735/24072, current 505.937286/24082: elapsed=108548.0us expected=107774.4us
(kms_flip:2760) DEBUG: expected 0, counted 130, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 0, counted 130, encoder type 2
(kms_flip:2760) DEBUG: expected 0, counted 130, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 0, counted 130, encoder type 2
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2760) igt_core-INFO: Stack trace:
(kms_flip:2760) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2760) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2760) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2760) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2760) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2760) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2760) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2760) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (6.098s)
Starting dynamic subtest: B-eDP1
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520)
(kms_flip:2760) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2760) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=8, pitch=11520)
(kms_flip:2760) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2760) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2760) igt_kms-INFO:   2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
(kms_flip:2760) DEBUG: No stale events found
(kms_flip:2760) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2760) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2760) INFO: Expected frametime: 11111us; measured 10958.4us +- 2.872us accuracy 0.08%
(kms_flip:2760) INFO: vblank interval differs from modeline! expected 11111.1us, measured 10958us +- 2.872us, difference 152.8us (53.2 sigma)
(kms_flip:2760) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 510.391907
current_received_ts = 510.391602
current_seq = 1062
count = 0
seq_step = 1
(kms_flip:2760) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 510.490509
current_received_ts = 510.490692
current_seq = 1071
count = 0
seq_step = 10
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.391907
last_received_ts = 510.391602
last_seq = 1062
current_ts = 510.501495
current_received_ts = 510.501648
current_seq = 1072
count = 1
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.391907/1062, current 510.501495/1072: elapsed=109583.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 510.490509
last_received_ts = 510.490692
last_seq = 1071
current_ts = 510.600098
current_received_ts = 510.600128
current_seq = 1081
count = 1
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 510.490509/1071, current 510.600098/1081: elapsed=109591.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.501495
last_received_ts = 510.501648
last_seq = 1072
current_ts = 510.611084
current_received_ts = 510.610962
current_seq = 1082
count = 2
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.501495/1072, current 510.611084/1082: elapsed=109590.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 510.600098
last_received_ts = 510.600128
last_seq = 1081
current_ts = 510.709686
current_received_ts = 510.709839
current_seq = 1091
count = 2
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 510.600098/1081, current 510.709686/1091: elapsed=109586.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.611084
last_received_ts = 510.610962
last_seq = 1082
current_ts = 510.720642
current_received_ts = 510.720734
current_seq = 1092
count = 3
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.611084/1082, current 510.720642/1092: elapsed=109582.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 510.709686
last_received_ts = 510.709839
last_seq = 1091
current_ts = 510.819275
current_received_ts = 510.819427
current_seq = 1101
count = 3
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 510.709686/1091, current 510.819275/1101: elapsed=109583.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.720642
last_received_ts = 510.720734
last_seq = 1092
current_ts = 510.830261
current_received_ts = 510.830475
current_seq = 1102
count = 4
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.720642/1092, current 510.830261/1102: elapsed=109605.0us expected=109583.8us +- 547.9us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 510.819275
last_received_ts = 510.819427
last_seq = 1101
current_ts = 510.929047
current_received_ts = 510.929199
current_seq = 1111
count = 4
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 510.819275/1101, current 510.929047/1111: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.830261
last_received_ts = 510.830475
last_seq = 1102
current_ts = 510.940033
current_received_ts = 510.940186
current_seq = 1112
count = 5
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.830261/1102, current 510.940033/1112: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 510.929047
last_received_ts = 510.929199
last_seq = 1111
current_ts = 511.038818
current_received_ts = 511.038971
current_seq = 1121
count = 5
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 510.929047/1111, current 511.038818/1121: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 510.940033
last_received_ts = 510.940186
last_seq = 1112
current_ts = 511.049805
current_received_ts = 511.049957
current_seq = 1122
count = 6
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 510.940033/1112, current 511.049805/1122: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.038818
last_received_ts = 511.038971
last_seq = 1121
current_ts = 511.148590
current_received_ts = 511.148743
current_seq = 1131
count = 6
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.038818/1121, current 511.148590/1131: elapsed=109773.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.049805
last_received_ts = 511.049957
last_seq = 1122
current_ts = 511.159576
current_received_ts = 511.159729
current_seq = 1132
count = 7
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.049805/1122, current 511.159576/1132: elapsed=109767.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.148590
last_received_ts = 511.148743
last_seq = 1131
current_ts = 511.258362
current_received_ts = 511.258453
current_seq = 1141
count = 7
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.148590/1131, current 511.258362/1141: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.159576
last_received_ts = 511.159729
last_seq = 1132
current_ts = 511.269348
current_received_ts = 511.269440
current_seq = 1142
count = 8
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.159576/1132, current 511.269348/1142: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.258362
last_received_ts = 511.258453
last_seq = 1141
current_ts = 511.368134
current_received_ts = 511.368286
current_seq = 1151
count = 8
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.258362/1141, current 511.368134/1151: elapsed=109764.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.269348
last_received_ts = 511.269440
last_seq = 1142
current_ts = 511.379120
current_received_ts = 511.379059
current_seq = 1152
count = 9
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.269348/1142, current 511.379120/1152: elapsed=109771.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.368134
last_received_ts = 511.368286
last_seq = 1151
current_ts = 511.477905
current_received_ts = 511.478088
current_seq = 1161
count = 9
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.368134/1151, current 511.477905/1161: elapsed=109776.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.379120
last_received_ts = 511.379059
last_seq = 1152
current_ts = 511.488892
current_received_ts = 511.489105
current_seq = 1162
count = 10
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.379120/1152, current 511.488892/1162: elapsed=109769.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.477905
last_received_ts = 511.478088
last_seq = 1161
current_ts = 511.587677
current_received_ts = 511.587830
current_seq = 1171
count = 10
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.477905/1161, current 511.587677/1171: elapsed=109765.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.488892
last_received_ts = 511.489105
last_seq = 1162
current_ts = 511.598663
current_received_ts = 511.598846
current_seq = 1172
count = 11
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.488892/1162, current 511.598663/1172: elapsed=109772.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.587677
last_received_ts = 511.587830
last_seq = 1171
current_ts = 511.697449
current_received_ts = 511.697601
current_seq = 1181
count = 11
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.587677/1171, current 511.697449/1181: elapsed=109775.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.598663
last_received_ts = 511.598846
last_seq = 1172
current_ts = 511.708435
current_received_ts = 511.708618
current_seq = 1182
count = 12
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.598663/1172, current 511.708435/1182: elapsed=109772.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.697449
last_received_ts = 511.697601
last_seq = 1181
current_ts = 511.807220
current_received_ts = 511.807159
current_seq = 1191
count = 12
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.697449/1181, current 511.807220/1191: elapsed=109772.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.708435
last_received_ts = 511.708618
last_seq = 1182
current_ts = 511.818207
current_received_ts = 511.818329
current_seq = 1192
count = 13
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.708435/1182, current 511.818207/1192: elapsed=109769.0us expected=109583.8us +- 547.9us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.807220
last_received_ts = 511.807159
last_seq = 1191
current_ts = 511.917114
current_received_ts = 511.917267
current_seq = 1201
count = 13
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.807220/1191, current 511.917114/1201: elapsed=109909.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.818207
last_received_ts = 511.818329
last_seq = 1192
current_ts = 511.928131
current_received_ts = 511.928345
current_seq = 1202
count = 14
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.818207/1192, current 511.928131/1202: elapsed=109927.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 511.917114
last_received_ts = 511.917267
last_seq = 1201
current_ts = 512.027039
current_received_ts = 512.027222
current_seq = 1211
count = 14
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 511.917114/1201, current 512.027039/1211: elapsed=109936.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 511.928131
last_received_ts = 511.928345
last_seq = 1202
current_ts = 512.038086
current_received_ts = 512.038208
current_seq = 1212
count = 15
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 511.928131/1202, current 512.038086/1212: elapsed=109936.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.027039
last_received_ts = 512.027222
last_seq = 1211
current_ts = 512.137024
current_received_ts = 512.137146
current_seq = 1221
count = 15
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.027039/1211, current 512.137024/1221: elapsed=109931.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.038086
last_received_ts = 512.038208
last_seq = 1212
current_ts = 512.148010
current_received_ts = 512.148132
current_seq = 1222
count = 16
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.038086/1212, current 512.148010/1222: elapsed=109929.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.137024
last_received_ts = 512.137146
last_seq = 1221
current_ts = 512.246948
current_received_ts = 512.247131
current_seq = 1231
count = 16
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.137024/1221, current 512.246948/1231: elapsed=109928.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.148010
last_received_ts = 512.148132
last_seq = 1222
current_ts = 512.257935
current_received_ts = 512.258057
current_seq = 1232
count = 17
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.148010/1222, current 512.257935/1232: elapsed=109928.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.246948
last_received_ts = 512.247131
last_seq = 1231
current_ts = 512.356873
current_received_ts = 512.357117
current_seq = 1241
count = 17
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.246948/1231, current 512.356873/1241: elapsed=109934.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.257935
last_received_ts = 512.258057
last_seq = 1232
current_ts = 512.367859
current_received_ts = 512.368042
current_seq = 1242
count = 18
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.257935/1232, current 512.367859/1242: elapsed=109935.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.356873
last_received_ts = 512.357117
last_seq = 1241
current_ts = 512.466797
current_received_ts = 512.466919
current_seq = 1251
count = 18
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.356873/1241, current 512.466797/1251: elapsed=109929.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.367859
last_received_ts = 512.368042
last_seq = 1242
current_ts = 512.477783
current_received_ts = 512.477905
current_seq = 1252
count = 19
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.367859/1242, current 512.477783/1252: elapsed=109928.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.466797
last_received_ts = 512.466919
last_seq = 1251
current_ts = 512.576721
current_received_ts = 512.576843
current_seq = 1261
count = 19
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.466797/1251, current 512.576721/1261: elapsed=109931.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.477783
last_received_ts = 512.477905
last_seq = 1252
current_ts = 512.587708
current_received_ts = 512.587891
current_seq = 1262
count = 20
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.477783/1252, current 512.587708/1262: elapsed=109933.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.576721
last_received_ts = 512.576843
last_seq = 1261
current_ts = 512.686646
current_received_ts = 512.686829
current_seq = 1271
count = 20
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.576721/1261, current 512.686646/1271: elapsed=109927.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.587708
last_received_ts = 512.587891
last_seq = 1262
current_ts = 512.697632
current_received_ts = 512.697815
current_seq = 1272
count = 21
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.587708/1262, current 512.697632/1272: elapsed=109930.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.686646
last_received_ts = 512.686829
last_seq = 1271
current_ts = 512.796570
current_received_ts = 512.796631
current_seq = 1281
count = 21
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.686646/1271, current 512.796570/1281: elapsed=109935.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.697632
last_received_ts = 512.697815
last_seq = 1272
current_ts = 512.807556
current_received_ts = 512.807739
current_seq = 1282
count = 22
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.697632/1272, current 512.807556/1282: elapsed=109935.0us expected=109583.8us +- 547.9us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.796570
last_received_ts = 512.796631
last_seq = 1281
current_ts = 512.906616
current_received_ts = 512.906799
current_seq = 1291
count = 22
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.796570/1281, current 512.906616/1291: elapsed=110045.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.807556
last_received_ts = 512.807739
last_seq = 1282
current_ts = 512.917603
current_received_ts = 512.917725
current_seq = 1292
count = 23
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.807556/1282, current 512.917603/1292: elapsed=110057.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 512.906616
last_received_ts = 512.906799
last_seq = 1291
current_ts = 513.016663
current_received_ts = 513.016846
current_seq = 1301
count = 23
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 512.906616/1291, current 513.016663/1301: elapsed=110069.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 512.917603
last_received_ts = 512.917725
last_seq = 1292
current_ts = 513.027710
current_received_ts = 513.027832
current_seq = 1302
count = 24
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 512.917603/1292, current 513.027710/1302: elapsed=110066.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.016663
last_received_ts = 513.016846
last_seq = 1301
current_ts = 513.126770
current_received_ts = 513.126892
current_seq = 1311
count = 24
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.016663/1301, current 513.126770/1311: elapsed=110073.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.027710
last_received_ts = 513.027832
last_seq = 1302
current_ts = 513.137756
current_received_ts = 513.137939
current_seq = 1312
count = 25
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.027710/1302, current 513.137756/1312: elapsed=110077.0us expected=109583.8us +- 547.9us, error 0.5%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.126770
last_received_ts = 513.126892
last_seq = 1311
current_ts = 513.236816
current_received_ts = 513.236633
current_seq = 1321
count = 25
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.126770/1311, current 513.236816/1321: elapsed=110073.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.137756
last_received_ts = 513.137939
last_seq = 1312
current_ts = 513.247864
current_received_ts = 513.247681
current_seq = 1322
count = 26
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.137756/1312, current 513.247864/1322: elapsed=110071.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.236816
last_received_ts = 513.236633
last_seq = 1321
current_ts = 513.346924
current_received_ts = 513.347107
current_seq = 1331
count = 26
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.236816/1321, current 513.346924/1331: elapsed=110071.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.247864
last_received_ts = 513.247681
last_seq = 1322
current_ts = 513.357910
current_received_ts = 513.358093
current_seq = 1332
count = 27
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.247864/1322, current 513.357910/1332: elapsed=110071.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.346924
last_received_ts = 513.347107
last_seq = 1331
current_ts = 513.456970
current_received_ts = 513.457153
current_seq = 1341
count = 27
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.346924/1331, current 513.456970/1341: elapsed=110070.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.357910
last_received_ts = 513.358093
last_seq = 1332
current_ts = 513.468018
current_received_ts = 513.468079
current_seq = 1342
count = 28
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.357910/1332, current 513.468018/1342: elapsed=110072.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.456970
last_received_ts = 513.457153
last_seq = 1341
current_ts = 513.567078
current_received_ts = 513.567200
current_seq = 1351
count = 28
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.456970/1341, current 513.567078/1351: elapsed=110073.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.468018
last_received_ts = 513.468079
last_seq = 1342
current_ts = 513.578064
current_received_ts = 513.578125
current_seq = 1352
count = 29
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.468018/1342, current 513.578064/1352: elapsed=110069.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.567078
last_received_ts = 513.567200
last_seq = 1351
current_ts = 513.677124
current_received_ts = 513.677246
current_seq = 1361
count = 29
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.567078/1351, current 513.677124/1361: elapsed=110067.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.578064
last_received_ts = 513.578125
last_seq = 1352
current_ts = 513.688110
current_received_ts = 513.688232
current_seq = 1362
count = 30
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.578064/1352, current 513.688110/1362: elapsed=110070.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.677124
last_received_ts = 513.677246
last_seq = 1361
current_ts = 513.787170
current_received_ts = 513.787354
current_seq = 1371
count = 30
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.677124/1361, current 513.787170/1371: elapsed=110074.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = flip
last_ts = 513.688110
last_received_ts = 513.688232
last_seq = 1362
current_ts = 513.798218
current_received_ts = 513.798279
current_seq = 1372
count = 31
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 513.688110/1362, current 513.798218/1372: elapsed=110073.0us expected=109583.8us +- 547.9us, error 0.4%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 513.787170
last_received_ts = 513.787354
last_seq = 1371
current_ts = 513.897339
current_received_ts = 513.897461
current_seq = 1381
count = 31
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 513.787170/1371, current 513.897339/1381: elapsed=110163.0us expected=109583.8us +- 547.9us, error 0.5%
(kms_flip:2760) DEBUG: inconsistent vblank ts/seq: last 513.787170/1371, current 513.897339/1381: elapsed=110163.0us expected=109583.8us
(kms_flip:2760) DEBUG: expected 0, counted 310, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 0, counted 310, encoder type 2
(kms_flip:2760) DEBUG: expected 0, counted 310, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 0, counted 310, encoder type 2
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2760) igt_core-INFO: Stack trace:
(kms_flip:2760) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2760) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2760) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2760) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2760) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2760) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2760) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2760) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.032s)
Starting dynamic subtest: C-eDP1
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.104004
last_received_ts = 519.104187
last_seq = 828
current_ts = 519.214600
current_received_ts = 519.214783
current_seq = 838
count = 8
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.104004/828, current 519.214600/838: elapsed=110609.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.203552
last_received_ts = 519.203735
last_seq = 837
current_ts = 519.314148
current_received_ts = 519.314331
current_seq = 847
count = 8
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.203552/837, current 519.314148/847: elapsed=110616.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.214600
last_received_ts = 519.214783
last_seq = 838
current_ts = 519.325256
current_received_ts = 519.325439
current_seq = 848
count = 9
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.214600/838, current 519.325256/848: elapsed=110615.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.314148
last_received_ts = 519.314331
last_seq = 847
current_ts = 519.424805
current_received_ts = 519.424744
current_seq = 857
count = 9
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.314148/847, current 519.424805/857: elapsed=110615.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.325256
last_received_ts = 519.325439
last_seq = 848
current_ts = 519.435852
current_received_ts = 519.435730
current_seq = 858
count = 10
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.325256/848, current 519.435852/858: elapsed=110617.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.424805
last_received_ts = 519.424744
last_seq = 857
current_ts = 519.535400
current_received_ts = 519.535522
current_seq = 867
count = 10
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.424805/857, current 519.535400/867: elapsed=110613.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.435852
last_received_ts = 519.435730
last_seq = 858
current_ts = 519.546448
current_received_ts = 519.546631
current_seq = 868
count = 11
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.435852/858, current 519.546448/868: elapsed=110612.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.535400
last_received_ts = 519.535522
last_seq = 867
current_ts = 519.645996
current_received_ts = 519.646179
current_seq = 877
count = 11
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.535400/867, current 519.645996/877: elapsed=110616.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.546448
last_received_ts = 519.546631
last_seq = 868
current_ts = 519.657104
current_received_ts = 519.657166
current_seq = 878
count = 12
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.546448/868, current 519.657104/878: elapsed=110616.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.645996
last_received_ts = 519.646179
last_seq = 877
current_ts = 519.756653
current_received_ts = 519.756775
current_seq = 887
count = 12
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.645996/877, current 519.756653/887: elapsed=110610.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.657104
last_received_ts = 519.657166
last_seq = 878
current_ts = 519.767700
current_received_ts = 519.767822
current_seq = 888
count = 13
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.657104/878, current 519.767700/888: elapsed=110611.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.756653
last_received_ts = 519.756775
last_seq = 887
current_ts = 519.867249
current_received_ts = 519.867432
current_seq = 897
count = 13
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.756653/887, current 519.867249/897: elapsed=110643.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.767700
last_received_ts = 519.767822
last_seq = 888
current_ts = 519.878357
current_received_ts = 519.878479
current_seq = 898
count = 14
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.767700/888, current 519.878357/898: elapsed=110650.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.867249
last_received_ts = 519.867432
last_seq = 897
current_ts = 519.977966
current_received_ts = 519.977966
current_seq = 907
count = 14
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.867249/897, current 519.977966/907: elapsed=110668.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.878357
last_received_ts = 519.878479
last_seq = 898
current_ts = 519.989014
current_received_ts = 519.989075
current_seq = 908
count = 15
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.878357/898, current 519.989014/908: elapsed=110667.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 519.977966
last_received_ts = 519.977966
last_seq = 907
current_ts = 520.088623
current_received_ts = 520.088745
current_seq = 917
count = 15
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 519.977966/907, current 520.088623/917: elapsed=110668.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 519.989014
last_received_ts = 519.989075
last_seq = 908
current_ts = 520.099670
current_received_ts = 520.099854
current_seq = 918
count = 16
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 519.989014/908, current 520.099670/918: elapsed=110669.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.088623
last_received_ts = 520.088745
last_seq = 917
current_ts = 520.199280
current_received_ts = 520.199402
current_seq = 927
count = 16
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.088623/917, current 520.199280/927: elapsed=110671.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.099670
last_received_ts = 520.099854
last_seq = 918
current_ts = 520.210327
current_received_ts = 520.210510
current_seq = 928
count = 17
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.099670/918, current 520.210327/928: elapsed=110670.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.199280
last_received_ts = 520.199402
last_seq = 927
current_ts = 520.309937
current_received_ts = 520.310120
current_seq = 937
count = 17
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.199280/927, current 520.309937/937: elapsed=110672.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.210327
last_received_ts = 520.210510
last_seq = 928
current_ts = 520.320984
current_received_ts = 520.321228
current_seq = 938
count = 18
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.210327/928, current 520.320984/938: elapsed=110665.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.309937
last_received_ts = 520.310120
last_seq = 937
current_ts = 520.420593
current_received_ts = 520.420776
current_seq = 947
count = 18
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.309937/937, current 520.420593/947: elapsed=110665.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.320984
last_received_ts = 520.321228
last_seq = 938
current_ts = 520.431702
current_received_ts = 520.431885
current_seq = 948
count = 19
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.320984/938, current 520.431702/948: elapsed=110671.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.420593
last_received_ts = 520.420776
last_seq = 947
current_ts = 520.531311
current_received_ts = 520.531433
current_seq = 957
count = 19
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.420593/947, current 520.531311/957: elapsed=110671.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.431702
last_received_ts = 520.431885
last_seq = 948
current_ts = 520.542358
current_received_ts = 520.542480
current_seq = 958
count = 20
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.431702/948, current 520.542358/958: elapsed=110672.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.531311
last_received_ts = 520.531433
last_seq = 957
current_ts = 520.641968
current_received_ts = 520.642151
current_seq = 967
count = 20
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.531311/957, current 520.641968/967: elapsed=110671.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.542358
last_received_ts = 520.542480
last_seq = 958
current_ts = 520.653015
current_received_ts = 520.653198
current_seq = 968
count = 21
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.542358/958, current 520.653015/968: elapsed=110670.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.641968
last_received_ts = 520.642151
last_seq = 967
current_ts = 520.752625
current_received_ts = 520.752563
current_seq = 977
count = 21
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.641968/967, current 520.752625/977: elapsed=110668.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.653015
last_received_ts = 520.653198
last_seq = 968
current_ts = 520.763672
current_received_ts = 520.763916
current_seq = 978
count = 22
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.653015/968, current 520.763672/978: elapsed=110669.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.752625
last_received_ts = 520.752563
last_seq = 977
current_ts = 520.863342
current_received_ts = 520.863464
current_seq = 987
count = 22
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.752625/977, current 520.863342/987: elapsed=110689.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.763672
last_received_ts = 520.763916
last_seq = 978
current_ts = 520.874390
current_received_ts = 520.874573
current_seq = 988
count = 23
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.763672/978, current 520.874390/988: elapsed=110692.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.863342
last_received_ts = 520.863464
last_seq = 987
current_ts = 520.974060
current_received_ts = 520.974182
current_seq = 997
count = 23
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.863342/987, current 520.974060/997: elapsed=110717.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.874390
last_received_ts = 520.874573
last_seq = 988
current_ts = 520.985107
current_received_ts = 520.985291
current_seq = 998
count = 24
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.874390/988, current 520.985107/998: elapsed=110717.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 520.974060
last_received_ts = 520.974182
last_seq = 997
current_ts = 521.084778
current_received_ts = 521.084900
current_seq = 1007
count = 24
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 520.974060/997, current 521.084778/1007: elapsed=110720.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 520.985107
last_received_ts = 520.985291
last_seq = 998
current_ts = 521.095825
current_received_ts = 521.096008
current_seq = 1008
count = 25
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 520.985107/998, current 521.095825/1008: elapsed=110717.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.084778
last_received_ts = 521.084900
last_seq = 1007
current_ts = 521.195496
current_received_ts = 521.195618
current_seq = 1017
count = 25
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.084778/1007, current 521.195496/1017: elapsed=110714.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.095825
last_received_ts = 521.096008
last_seq = 1008
current_ts = 521.206543
current_received_ts = 521.206604
current_seq = 1018
count = 26
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.095825/1008, current 521.206543/1018: elapsed=110717.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.195496
last_received_ts = 521.195618
last_seq = 1017
current_ts = 521.306213
current_received_ts = 521.306335
current_seq = 1027
count = 26
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.195496/1017, current 521.306213/1027: elapsed=110717.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.206543
last_received_ts = 521.206604
last_seq = 1018
current_ts = 521.317261
current_received_ts = 521.317444
current_seq = 1028
count = 27
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.206543/1018, current 521.317261/1028: elapsed=110720.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.306213
last_received_ts = 521.306335
last_seq = 1027
current_ts = 521.416931
current_received_ts = 521.417175
current_seq = 1037
count = 27
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.306213/1027, current 521.416931/1037: elapsed=110721.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.317261
last_received_ts = 521.317444
last_seq = 1028
current_ts = 521.427979
current_received_ts = 521.428101
current_seq = 1038
count = 28
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.317261/1028, current 521.427979/1038: elapsed=110718.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.416931
last_received_ts = 521.417175
last_seq = 1037
current_ts = 521.527649
current_received_ts = 521.527771
current_seq = 1047
count = 28
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.416931/1037, current 521.527649/1047: elapsed=110716.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.427979
last_received_ts = 521.428101
last_seq = 1038
current_ts = 521.538696
current_received_ts = 521.538879
current_seq = 1048
count = 29
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.427979/1038, current 521.538696/1048: elapsed=110716.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.527649
last_received_ts = 521.527771
last_seq = 1047
current_ts = 521.638367
current_received_ts = 521.638550
current_seq = 1057
count = 29
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.527649/1047, current 521.638367/1057: elapsed=110720.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.538696
last_received_ts = 521.538879
last_seq = 1048
current_ts = 521.649414
current_received_ts = 521.649475
current_seq = 1058
count = 30
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.538696/1048, current 521.649414/1058: elapsed=110720.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.638367
last_received_ts = 521.638550
last_seq = 1057
current_ts = 521.749023
current_received_ts = 521.749207
current_seq = 1067
count = 30
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.638367/1057, current 521.749023/1067: elapsed=110713.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.649414
last_received_ts = 521.649475
last_seq = 1058
current_ts = 521.760132
current_received_ts = 521.760254
current_seq = 1068
count = 31
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.649414/1058, current 521.760132/1068: elapsed=110714.0us expected=110550.6us +- 552.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.749023
last_received_ts = 521.749207
last_seq = 1067
current_ts = 521.859802
current_received_ts = 521.859924
current_seq = 1077
count = 31
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.749023/1067, current 521.859802/1077: elapsed=110736.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.760132
last_received_ts = 521.760254
last_seq = 1068
current_ts = 521.870850
current_received_ts = 521.871094
current_seq = 1078
count = 32
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.760132/1068, current 521.870850/1078: elapsed=110742.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.859802
last_received_ts = 521.859924
last_seq = 1077
current_ts = 521.970520
current_received_ts = 521.970703
current_seq = 1087
count = 32
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.859802/1077, current 521.970520/1087: elapsed=110761.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.870850
last_received_ts = 521.871094
last_seq = 1078
current_ts = 521.981628
current_received_ts = 521.981750
current_seq = 1088
count = 33
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.870850/1078, current 521.981628/1088: elapsed=110756.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 521.970520
last_received_ts = 521.970703
last_seq = 1087
current_ts = 522.081299
current_received_ts = 522.081421
current_seq = 1097
count = 33
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 521.970520/1087, current 522.081299/1097: elapsed=110758.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 521.981628
last_received_ts = 521.981750
last_seq = 1088
current_ts = 522.092407
current_received_ts = 522.092468
current_seq = 1098
count = 34
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 521.981628/1088, current 522.092407/1098: elapsed=110762.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.081299
last_received_ts = 522.081421
last_seq = 1097
current_ts = 522.192078
current_received_ts = 522.192261
current_seq = 1107
count = 34
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.081299/1097, current 522.192078/1107: elapsed=110763.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.092407
last_received_ts = 522.092468
last_seq = 1098
current_ts = 522.203125
current_received_ts = 522.203308
current_seq = 1108
count = 35
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.092407/1098, current 522.203125/1108: elapsed=110762.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.192078
last_received_ts = 522.192261
last_seq = 1107
current_ts = 522.302856
current_received_ts = 522.302979
current_seq = 1117
count = 35
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.192078/1107, current 522.302856/1117: elapsed=110757.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.203125
last_received_ts = 522.203308
last_seq = 1108
current_ts = 522.313904
current_received_ts = 522.313782
current_seq = 1118
count = 36
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.203125/1108, current 522.313904/1118: elapsed=110758.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.302856
last_received_ts = 522.302979
last_seq = 1117
current_ts = 522.413574
current_received_ts = 522.413696
current_seq = 1127
count = 36
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.302856/1117, current 522.413574/1127: elapsed=110759.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.313904
last_received_ts = 522.313782
last_seq = 1118
current_ts = 522.424683
current_received_ts = 522.424561
current_seq = 1128
count = 37
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.313904/1118, current 522.424683/1128: elapsed=110759.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.413574
last_received_ts = 522.413696
last_seq = 1127
current_ts = 522.524353
current_received_ts = 522.524475
current_seq = 1137
count = 37
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.413574/1127, current 522.524353/1137: elapsed=110765.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.424683
last_received_ts = 522.424561
last_seq = 1128
current_ts = 522.535400
current_received_ts = 522.535583
current_seq = 1138
count = 38
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.424683/1128, current 522.535400/1138: elapsed=110762.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.524353
last_received_ts = 522.524475
last_seq = 1137
current_ts = 522.635132
current_received_ts = 522.635254
current_seq = 1147
count = 38
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.524353/1137, current 522.635132/1147: elapsed=110758.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.535400
last_received_ts = 522.535583
last_seq = 1138
current_ts = 522.646179
current_received_ts = 522.646362
current_seq = 1148
count = 39
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.535400/1138, current 522.646179/1148: elapsed=110756.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.635132
last_received_ts = 522.635254
last_seq = 1147
current_ts = 522.745850
current_received_ts = 522.745789
current_seq = 1157
count = 39
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.635132/1147, current 522.745850/1157: elapsed=110756.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.646179
last_received_ts = 522.646362
last_seq = 1148
current_ts = 522.756958
current_received_ts = 522.757080
current_seq = 1158
count = 40
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.646179/1148, current 522.756958/1158: elapsed=110761.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.745850
last_received_ts = 522.745789
last_seq = 1157
current_ts = 522.856628
current_received_ts = 522.856812
current_seq = 1167
count = 40
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.745850/1157, current 522.856628/1167: elapsed=110773.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.756958
last_received_ts = 522.757080
last_seq = 1158
current_ts = 522.867737
current_received_ts = 522.867798
current_seq = 1168
count = 41
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.756958/1158, current 522.867737/1168: elapsed=110775.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.856628
last_received_ts = 522.856812
last_seq = 1167
current_ts = 522.967468
current_received_ts = 522.967529
current_seq = 1177
count = 41
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.856628/1167, current 522.967468/1177: elapsed=110800.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.867737
last_received_ts = 522.867798
last_seq = 1168
current_ts = 522.978516
current_received_ts = 522.978699
current_seq = 1178
count = 42
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.867737/1168, current 522.978516/1178: elapsed=110796.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 522.967468
last_received_ts = 522.967529
last_seq = 1177
current_ts = 523.078247
current_received_ts = 523.078308
current_seq = 1187
count = 42
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 522.967468/1177, current 523.078247/1187: elapsed=110796.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 522.978516
last_received_ts = 522.978699
last_seq = 1178
current_ts = 523.089294
current_received_ts = 523.089478
current_seq = 1188
count = 43
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 522.978516/1178, current 523.089294/1188: elapsed=110800.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.078247
last_received_ts = 523.078308
last_seq = 1187
current_ts = 523.189026
current_received_ts = 523.189209
current_seq = 1197
count = 43
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.078247/1187, current 523.189026/1197: elapsed=110795.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.089294
last_received_ts = 523.089478
last_seq = 1188
current_ts = 523.200134
current_received_ts = 523.200195
current_seq = 1198
count = 44
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.089294/1188, current 523.200134/1198: elapsed=110794.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.189026
last_received_ts = 523.189209
last_seq = 1197
current_ts = 523.299805
current_received_ts = 523.299988
current_seq = 1207
count = 44
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.189026/1197, current 523.299805/1207: elapsed=110796.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.200134
last_received_ts = 523.200195
last_seq = 1198
current_ts = 523.310913
current_received_ts = 523.311096
current_seq = 1208
count = 45
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.200134/1198, current 523.310913/1208: elapsed=110797.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.299805
last_received_ts = 523.299988
last_seq = 1207
current_ts = 523.410645
current_received_ts = 523.410767
current_seq = 1217
count = 45
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.299805/1207, current 523.410645/1217: elapsed=110799.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.310913
last_received_ts = 523.311096
last_seq = 1208
current_ts = 523.421692
current_received_ts = 523.421631
current_seq = 1218
count = 46
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.310913/1208, current 523.421692/1218: elapsed=110800.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.410645
last_received_ts = 523.410767
last_seq = 1217
current_ts = 523.521423
current_received_ts = 523.521545
current_seq = 1227
count = 46
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.410645/1217, current 523.521423/1227: elapsed=110795.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.421692
last_received_ts = 523.421631
last_seq = 1218
current_ts = 523.532532
current_received_ts = 523.532654
current_seq = 1228
count = 47
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.421692/1218, current 523.532532/1228: elapsed=110799.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.521423
last_received_ts = 523.521545
last_seq = 1227
current_ts = 523.632202
current_received_ts = 523.632385
current_seq = 1237
count = 47
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.521423/1227, current 523.632202/1237: elapsed=110797.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.532532
last_received_ts = 523.532654
last_seq = 1228
current_ts = 523.643311
current_received_ts = 523.643433
current_seq = 1238
count = 48
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.532532/1228, current 523.643311/1238: elapsed=110794.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.632202
last_received_ts = 523.632385
last_seq = 1237
current_ts = 523.743042
current_received_ts = 523.743164
current_seq = 1247
count = 48
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.632202/1237, current 523.743042/1247: elapsed=110798.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.643311
last_received_ts = 523.643433
last_seq = 1238
current_ts = 523.754089
current_received_ts = 523.754272
current_seq = 1248
count = 49
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.643311/1238, current 523.754089/1248: elapsed=110795.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.743042
last_received_ts = 523.743164
last_seq = 1247
current_ts = 523.853821
current_received_ts = 523.853943
current_seq = 1257
count = 49
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.743042/1247, current 523.853821/1257: elapsed=110806.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.754089
last_received_ts = 523.754272
last_seq = 1248
current_ts = 523.864929
current_received_ts = 523.865112
current_seq = 1258
count = 50
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.754089/1248, current 523.864929/1258: elapsed=110813.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.853821
last_received_ts = 523.853943
last_seq = 1257
current_ts = 523.964661
current_received_ts = 523.964661
current_seq = 1267
count = 50
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.853821/1257, current 523.964661/1267: elapsed=110829.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.864929
last_received_ts = 523.865112
last_seq = 1258
current_ts = 523.975708
current_received_ts = 523.975891
current_seq = 1268
count = 51
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.864929/1258, current 523.975708/1268: elapsed=110827.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 523.964661
last_received_ts = 523.964661
last_seq = 1267
current_ts = 524.075500
current_received_ts = 524.075623
current_seq = 1277
count = 51
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 523.964661/1267, current 524.075500/1277: elapsed=110832.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 523.975708
last_received_ts = 523.975891
last_seq = 1268
current_ts = 524.086548
current_received_ts = 524.086731
current_seq = 1278
count = 52
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 523.975708/1268, current 524.086548/1278: elapsed=110832.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.075500
last_received_ts = 524.075623
last_seq = 1277
current_ts = 524.186279
current_received_ts = 524.186462
current_seq = 1287
count = 52
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.075500/1277, current 524.186279/1287: elapsed=110827.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.086548
last_received_ts = 524.086731
last_seq = 1278
current_ts = 524.197388
current_received_ts = 524.197571
current_seq = 1288
count = 53
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.086548/1278, current 524.197388/1288: elapsed=110826.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.186279
last_received_ts = 524.186462
last_seq = 1287
current_ts = 524.297119
current_received_ts = 524.297302
current_seq = 1297
count = 53
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.186279/1287, current 524.297119/1297: elapsed=110828.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.197388
last_received_ts = 524.197571
last_seq = 1288
current_ts = 524.308228
current_received_ts = 524.308411
current_seq = 1298
count = 54
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.197388/1288, current 524.308228/1298: elapsed=110829.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.297119
last_received_ts = 524.297302
last_seq = 1297
current_ts = 524.407959
current_received_ts = 524.408203
current_seq = 1307
count = 54
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.297119/1297, current 524.407959/1307: elapsed=110831.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.308228
last_received_ts = 524.308411
last_seq = 1298
current_ts = 524.419067
current_received_ts = 524.419250
current_seq = 1308
count = 55
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.308228/1298, current 524.419067/1308: elapsed=110830.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.407959
last_received_ts = 524.408203
last_seq = 1307
current_ts = 524.518799
current_received_ts = 524.518982
current_seq = 1317
count = 55
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.407959/1307, current 524.518799/1317: elapsed=110831.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.419067
last_received_ts = 524.419250
last_seq = 1308
current_ts = 524.529907
current_received_ts = 524.529968
current_seq = 1318
count = 56
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.419067/1308, current 524.529907/1318: elapsed=110833.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.518799
last_received_ts = 524.518982
last_seq = 1317
current_ts = 524.629639
current_received_ts = 524.629761
current_seq = 1327
count = 56
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.518799/1317, current 524.629639/1327: elapsed=110830.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.529907
last_received_ts = 524.529968
last_seq = 1318
current_ts = 524.640686
current_received_ts = 524.640869
current_seq = 1328
count = 57
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.529907/1318, current 524.640686/1328: elapsed=110827.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.629639
last_received_ts = 524.629761
last_seq = 1327
current_ts = 524.740479
current_received_ts = 524.740479
current_seq = 1337
count = 57
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.629639/1327, current 524.740479/1337: elapsed=110825.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.640686
last_received_ts = 524.640869
last_seq = 1328
current_ts = 524.751526
current_received_ts = 524.751648
current_seq = 1338
count = 58
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.640686/1328, current 524.751526/1338: elapsed=110827.0us expected=110550.6us +- 552.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.740479
last_received_ts = 524.740479
last_seq = 1337
current_ts = 524.851318
current_received_ts = 524.851440
current_seq = 1347
count = 58
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.740479/1337, current 524.851318/1347: elapsed=110841.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.751526
last_received_ts = 524.751648
last_seq = 1338
current_ts = 524.862366
current_received_ts = 524.862549
current_seq = 1348
count = 59
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.751526/1338, current 524.862366/1348: elapsed=110846.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.851318
last_received_ts = 524.851440
last_seq = 1347
current_ts = 524.962158
current_received_ts = 524.962280
current_seq = 1357
count = 59
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.851318/1347, current 524.962158/1357: elapsed=110857.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.862366
last_received_ts = 524.862549
last_seq = 1348
current_ts = 524.973206
current_received_ts = 524.973389
current_seq = 1358
count = 60
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.862366/1348, current 524.973206/1358: elapsed=110853.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 524.962158
last_received_ts = 524.962280
last_seq = 1357
current_ts = 525.072998
current_received_ts = 525.073181
current_seq = 1367
count = 60
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 524.962158/1357, current 525.072998/1367: elapsed=110855.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 524.973206
last_received_ts = 524.973389
last_seq = 1358
current_ts = 525.084106
current_received_ts = 525.084167
current_seq = 1368
count = 61
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 524.973206/1358, current 525.084106/1368: elapsed=110857.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.072998
last_received_ts = 525.073181
last_seq = 1367
current_ts = 525.183838
current_received_ts = 525.184082
current_seq = 1377
count = 61
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.072998/1367, current 525.183838/1377: elapsed=110860.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.084106
last_received_ts = 525.084167
last_seq = 1368
current_ts = 525.194946
current_received_ts = 525.195129
current_seq = 1378
count = 62
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.084106/1368, current 525.194946/1378: elapsed=110860.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.183838
last_received_ts = 525.184082
last_seq = 1377
current_ts = 525.294739
current_received_ts = 525.294861
current_seq = 1387
count = 62
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.183838/1377, current 525.294739/1387: elapsed=110857.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.194946
last_received_ts = 525.195129
last_seq = 1378
current_ts = 525.305786
current_received_ts = 525.305969
current_seq = 1388
count = 63
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.194946/1378, current 525.305786/1388: elapsed=110858.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.294739
last_received_ts = 525.294861
last_seq = 1387
current_ts = 525.405579
current_received_ts = 525.405762
current_seq = 1397
count = 63
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.294739/1387, current 525.405579/1397: elapsed=110858.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.305786
last_received_ts = 525.305969
last_seq = 1388
current_ts = 525.416687
current_received_ts = 525.416809
current_seq = 1398
count = 64
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.305786/1388, current 525.416687/1398: elapsed=110857.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.405579
last_received_ts = 525.405762
last_seq = 1397
current_ts = 525.516418
current_received_ts = 525.516602
current_seq = 1407
count = 64
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.405579/1397, current 525.516418/1407: elapsed=110858.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.416687
last_received_ts = 525.416809
last_seq = 1398
current_ts = 525.527527
current_received_ts = 525.527710
current_seq = 1408
count = 65
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.416687/1398, current 525.527527/1408: elapsed=110858.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.516418
last_received_ts = 525.516602
last_seq = 1407
current_ts = 525.627319
current_received_ts = 525.627441
current_seq = 1417
count = 65
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.516418/1407, current 525.627319/1417: elapsed=110860.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.527527
last_received_ts = 525.527710
last_seq = 1408
current_ts = 525.638367
current_received_ts = 525.638550
current_seq = 1418
count = 66
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.527527/1408, current 525.638367/1418: elapsed=110856.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.627319
last_received_ts = 525.627441
last_seq = 1417
current_ts = 525.738159
current_received_ts = 525.738281
current_seq = 1427
count = 66
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.627319/1417, current 525.738159/1427: elapsed=110856.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 525.638367
last_received_ts = 525.638550
last_seq = 1418
current_ts = 525.749268
current_received_ts = 525.749451
current_seq = 1428
count = 67
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 525.638367/1418, current 525.749268/1428: elapsed=110858.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 525.738159
last_received_ts = 525.738281
last_seq = 1427
current_ts = 525.848999
current_received_ts = 525.849182
current_seq = 1437
count = 67
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 525.738159/1427, current 525.848999/1437: elapsed=110862.0us expected=110550.6us +- 552.8us, error 0.3%
(kms_flip:2760) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2760) igt_core-INFO: Stack trace:
(kms_flip:2760) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2760) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2760) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2760) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2760) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2760) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2760) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2760) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (12.435s)
Starting dynamic subtest: D-eDP1
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest D-eDP1 failed.
**** DEBUG ****
(kms_flip:2760) DEBUG: name = flip
last_ts = 531.526306
last_received_ts = 531.526428
last_seq = 1165
current_ts = 531.637268
current_received_ts = 531.637451
current_seq = 1175
count = 8
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 531.526306/1165, current 531.637268/1175: elapsed=110968.0us expected=110953.1us +- 554.8us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 531.626160
last_received_ts = 531.626343
last_seq = 1174
current_ts = 531.737122
current_received_ts = 531.737183
current_seq = 1184
count = 8
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 531.626160/1174, current 531.737122/1184: elapsed=110962.0us expected=110953.1us +- 554.8us, error 0.0%
(kms_flip:2760) DEBUG: name = flip
last_ts = 531.637268
last_received_ts = 531.637451
last_seq = 1175
current_ts = 531.748230
current_received_ts = 531.748352
current_seq = 1185
count = 9
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 531.637268/1175, current 531.748230/1185: elapsed=110968.0us expected=110953.1us +- 554.8us, error 0.0%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 531.737122
last_received_ts = 531.737183
last_seq = 1184
current_ts = 531.848206
current_received_ts = 531.848083
current_seq = 1194
count = 9
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 531.737122/1184, current 531.848206/1194: elapsed=111065.0us expected=110953.1us +- 554.8us, error 0.1%
(kms_flip:2760) DEBUG: name = flip
last_ts = 531.748230
last_received_ts = 531.748352
last_seq = 1185
current_ts = 531.859314
current_received_ts = 531.859375
current_seq = 1195
count = 10
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 531.748230/1185, current 531.859314/1195: elapsed=111095.0us expected=110953.1us +- 554.8us, error 0.1%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 531.848206
last_received_ts = 531.848083
last_seq = 1194
current_ts = 531.959473
current_received_ts = 531.959656
current_seq = 1204
count = 10
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 531.848206/1194, current 531.959473/1204: elapsed=111295.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 531.859314
last_received_ts = 531.859375
last_seq = 1195
current_ts = 531.970642
current_received_ts = 531.970825
current_seq = 1205
count = 11
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 531.859314/1195, current 531.970642/1205: elapsed=111294.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 531.959473
last_received_ts = 531.959656
last_seq = 1204
current_ts = 532.070801
current_received_ts = 532.070923
current_seq = 1214
count = 11
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 531.959473/1204, current 532.070801/1214: elapsed=111295.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 531.970642
last_received_ts = 531.970825
last_seq = 1205
current_ts = 532.081909
current_received_ts = 532.082153
current_seq = 1215
count = 12
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 531.970642/1205, current 532.081909/1215: elapsed=111294.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.070801
last_received_ts = 532.070923
last_seq = 1214
current_ts = 532.182068
current_received_ts = 532.182251
current_seq = 1224
count = 12
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.070801/1214, current 532.182068/1224: elapsed=111294.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.081909
last_received_ts = 532.082153
last_seq = 1215
current_ts = 532.193176
current_received_ts = 532.193420
current_seq = 1225
count = 13
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.081909/1215, current 532.193176/1225: elapsed=111295.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.182068
last_received_ts = 532.182251
last_seq = 1224
current_ts = 532.293396
current_received_ts = 532.293518
current_seq = 1234
count = 13
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.182068/1224, current 532.293396/1234: elapsed=111300.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.193176
last_received_ts = 532.193420
last_seq = 1225
current_ts = 532.304504
current_received_ts = 532.304626
current_seq = 1235
count = 14
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.193176/1225, current 532.304504/1235: elapsed=111296.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.293396
last_received_ts = 532.293518
last_seq = 1234
current_ts = 532.404663
current_received_ts = 532.404785
current_seq = 1244
count = 14
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.293396/1234, current 532.404663/1244: elapsed=111294.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.304504
last_received_ts = 532.304626
last_seq = 1235
current_ts = 532.415771
current_received_ts = 532.415894
current_seq = 1245
count = 15
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.304504/1235, current 532.415771/1245: elapsed=111296.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.404663
last_received_ts = 532.404785
last_seq = 1244
current_ts = 532.515991
current_received_ts = 532.516174
current_seq = 1254
count = 15
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.404663/1244, current 532.515991/1254: elapsed=111292.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.415771
last_received_ts = 532.415894
last_seq = 1245
current_ts = 532.527100
current_received_ts = 532.526978
current_seq = 1255
count = 16
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.415771/1245, current 532.527100/1255: elapsed=111294.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.515991
last_received_ts = 532.516174
last_seq = 1254
current_ts = 532.627258
current_received_ts = 532.627380
current_seq = 1264
count = 16
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.515991/1254, current 532.627258/1264: elapsed=111299.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.527100
last_received_ts = 532.526978
last_seq = 1255
current_ts = 532.638367
current_received_ts = 532.638489
current_seq = 1265
count = 17
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.527100/1255, current 532.638367/1265: elapsed=111298.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.627258
last_received_ts = 532.627380
last_seq = 1264
current_ts = 532.738586
current_received_ts = 532.738708
current_seq = 1274
count = 17
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.627258/1264, current 532.738586/1274: elapsed=111297.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.638367
last_received_ts = 532.638489
last_seq = 1265
current_ts = 532.749695
current_received_ts = 532.749634
current_seq = 1275
count = 18
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.638367/1265, current 532.749695/1275: elapsed=111298.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.738586
last_received_ts = 532.738708
last_seq = 1274
current_ts = 532.849854
current_received_ts = 532.850098
current_seq = 1284
count = 18
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.738586/1274, current 532.849854/1284: elapsed=111289.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.749695
last_received_ts = 532.749634
last_seq = 1275
current_ts = 532.860962
current_received_ts = 532.861145
current_seq = 1285
count = 19
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.749695/1275, current 532.860962/1285: elapsed=111288.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.849854
last_received_ts = 532.850098
last_seq = 1284
current_ts = 532.961121
current_received_ts = 532.961304
current_seq = 1294
count = 19
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.849854/1284, current 532.961121/1294: elapsed=111285.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.860962
last_received_ts = 532.861145
last_seq = 1285
current_ts = 532.972290
current_received_ts = 532.972412
current_seq = 1295
count = 20
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.860962/1285, current 532.972290/1295: elapsed=111286.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 532.961121
last_received_ts = 532.961304
last_seq = 1294
current_ts = 533.072388
current_received_ts = 533.072571
current_seq = 1304
count = 20
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 532.961121/1294, current 533.072388/1304: elapsed=111284.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 532.972290
last_received_ts = 532.972412
last_seq = 1295
current_ts = 533.083557
current_received_ts = 533.083740
current_seq = 1305
count = 21
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 532.972290/1295, current 533.083557/1305: elapsed=111281.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.072388
last_received_ts = 533.072571
last_seq = 1304
current_ts = 533.183716
current_received_ts = 533.183899
current_seq = 1314
count = 21
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.072388/1304, current 533.183716/1314: elapsed=111282.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.083557
last_received_ts = 533.083740
last_seq = 1305
current_ts = 533.194824
current_received_ts = 533.195068
current_seq = 1315
count = 22
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.083557/1305, current 533.194824/1315: elapsed=111283.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.183716
last_received_ts = 533.183899
last_seq = 1314
current_ts = 533.294983
current_received_ts = 533.295166
current_seq = 1324
count = 22
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.183716/1314, current 533.294983/1324: elapsed=111279.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.194824
last_received_ts = 533.195068
last_seq = 1315
current_ts = 533.306091
current_received_ts = 533.306274
current_seq = 1325
count = 23
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.194824/1315, current 533.306091/1325: elapsed=111283.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.294983
last_received_ts = 533.295166
last_seq = 1324
current_ts = 533.406250
current_received_ts = 533.406433
current_seq = 1334
count = 23
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.294983/1324, current 533.406250/1334: elapsed=111285.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.306091
last_received_ts = 533.306274
last_seq = 1325
current_ts = 533.417419
current_received_ts = 533.417542
current_seq = 1335
count = 24
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.306091/1325, current 533.417419/1335: elapsed=111284.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.406250
last_received_ts = 533.406433
last_seq = 1334
current_ts = 533.517517
current_received_ts = 533.517700
current_seq = 1344
count = 24
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.406250/1334, current 533.517517/1344: elapsed=111281.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.417419
last_received_ts = 533.417542
last_seq = 1335
current_ts = 533.528687
current_received_ts = 533.528809
current_seq = 1345
count = 25
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.417419/1335, current 533.528687/1345: elapsed=111281.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.517517
last_received_ts = 533.517700
last_seq = 1344
current_ts = 533.628845
current_received_ts = 533.628967
current_seq = 1354
count = 25
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.517517/1344, current 533.628845/1354: elapsed=111286.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.528687
last_received_ts = 533.528809
last_seq = 1345
current_ts = 533.639954
current_received_ts = 533.640076
current_seq = 1355
count = 26
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.528687/1345, current 533.639954/1355: elapsed=111284.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.628845
last_received_ts = 533.628967
last_seq = 1354
current_ts = 533.740112
current_received_ts = 533.740234
current_seq = 1364
count = 26
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.628845/1354, current 533.740112/1364: elapsed=111279.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.639954
last_received_ts = 533.640076
last_seq = 1355
current_ts = 533.751221
current_received_ts = 533.751404
current_seq = 1365
count = 27
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.639954/1355, current 533.751221/1365: elapsed=111280.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.740112
last_received_ts = 533.740234
last_seq = 1364
current_ts = 533.851379
current_received_ts = 533.851562
current_seq = 1374
count = 27
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.740112/1364, current 533.851379/1374: elapsed=111280.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.751221
last_received_ts = 533.751404
last_seq = 1365
current_ts = 533.862488
current_received_ts = 533.862732
current_seq = 1375
count = 28
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.751221/1365, current 533.862488/1375: elapsed=111280.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.851379
last_received_ts = 533.851562
last_seq = 1374
current_ts = 533.962646
current_received_ts = 533.962830
current_seq = 1384
count = 28
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.851379/1374, current 533.962646/1384: elapsed=111269.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.862488
last_received_ts = 533.862732
last_seq = 1375
current_ts = 533.973755
current_received_ts = 533.973938
current_seq = 1385
count = 29
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.862488/1375, current 533.973755/1385: elapsed=111266.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 533.962646
last_received_ts = 533.962830
last_seq = 1384
current_ts = 534.073914
current_received_ts = 534.074158
current_seq = 1394
count = 29
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 533.962646/1384, current 534.073914/1394: elapsed=111272.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 533.973755
last_received_ts = 533.973938
last_seq = 1385
current_ts = 534.085083
current_received_ts = 534.085205
current_seq = 1395
count = 30
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 533.973755/1385, current 534.085083/1395: elapsed=111272.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.073914
last_received_ts = 534.074158
last_seq = 1394
current_ts = 534.185181
current_received_ts = 534.185303
current_seq = 1404
count = 30
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.073914/1394, current 534.185181/1404: elapsed=111267.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.085083
last_received_ts = 534.085205
last_seq = 1395
current_ts = 534.196350
current_received_ts = 534.196533
current_seq = 1405
count = 31
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.085083/1395, current 534.196350/1405: elapsed=111271.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.185181
last_received_ts = 534.185303
last_seq = 1404
current_ts = 534.296448
current_received_ts = 534.296631
current_seq = 1414
count = 31
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.185181/1404, current 534.296448/1414: elapsed=111273.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.196350
last_received_ts = 534.196533
last_seq = 1405
current_ts = 534.307617
current_received_ts = 534.307800
current_seq = 1415
count = 32
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.196350/1405, current 534.307617/1415: elapsed=111268.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.296448
last_received_ts = 534.296631
last_seq = 1414
current_ts = 534.407715
current_received_ts = 534.407898
current_seq = 1424
count = 32
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.296448/1414, current 534.407715/1424: elapsed=111268.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.307617
last_received_ts = 534.307800
last_seq = 1415
current_ts = 534.418884
current_received_ts = 534.419067
current_seq = 1425
count = 33
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.307617/1415, current 534.418884/1425: elapsed=111271.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.407715
last_received_ts = 534.407898
last_seq = 1424
current_ts = 534.518982
current_received_ts = 534.519165
current_seq = 1434
count = 33
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.407715/1424, current 534.518982/1434: elapsed=111272.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.418884
last_received_ts = 534.419067
last_seq = 1425
current_ts = 534.530151
current_received_ts = 534.530334
current_seq = 1435
count = 34
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.418884/1425, current 534.530151/1435: elapsed=111269.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.518982
last_received_ts = 534.519165
last_seq = 1434
current_ts = 534.630249
current_received_ts = 534.630432
current_seq = 1444
count = 34
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.518982/1434, current 534.630249/1444: elapsed=111268.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.530151
last_received_ts = 534.530334
last_seq = 1435
current_ts = 534.641418
current_received_ts = 534.641602
current_seq = 1445
count = 35
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.530151/1435, current 534.641418/1445: elapsed=111269.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.630249
last_received_ts = 534.630432
last_seq = 1444
current_ts = 534.741577
current_received_ts = 534.741699
current_seq = 1454
count = 35
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.630249/1444, current 534.741577/1454: elapsed=111272.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.641418
last_received_ts = 534.641602
last_seq = 1445
current_ts = 534.752686
current_received_ts = 534.752869
current_seq = 1455
count = 36
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.641418/1445, current 534.752686/1455: elapsed=111272.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.741577
last_received_ts = 534.741699
last_seq = 1454
current_ts = 534.852844
current_received_ts = 534.852966
current_seq = 1464
count = 36
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.741577/1454, current 534.852844/1464: elapsed=111267.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.752686
last_received_ts = 534.752869
last_seq = 1455
current_ts = 534.863953
current_received_ts = 534.864136
current_seq = 1465
count = 37
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.752686/1455, current 534.863953/1465: elapsed=111265.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.852844
last_received_ts = 534.852966
last_seq = 1464
current_ts = 534.964050
current_received_ts = 534.964233
current_seq = 1474
count = 37
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.852844/1464, current 534.964050/1474: elapsed=111253.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.863953
last_received_ts = 534.864136
last_seq = 1465
current_ts = 534.975220
current_received_ts = 534.975403
current_seq = 1475
count = 38
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.863953/1465, current 534.975220/1475: elapsed=111258.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 534.964050
last_received_ts = 534.964233
last_seq = 1474
current_ts = 535.075317
current_received_ts = 535.075500
current_seq = 1484
count = 38
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 534.964050/1474, current 535.075317/1484: elapsed=111259.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 534.975220
last_received_ts = 534.975403
last_seq = 1475
current_ts = 535.086426
current_received_ts = 535.086609
current_seq = 1485
count = 39
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 534.975220/1475, current 535.086426/1485: elapsed=111256.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.075317
last_received_ts = 535.075500
last_seq = 1484
current_ts = 535.186584
current_received_ts = 535.186523
current_seq = 1494
count = 39
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.075317/1484, current 535.186584/1494: elapsed=111258.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.086426
last_received_ts = 535.086609
last_seq = 1485
current_ts = 535.197693
current_received_ts = 535.197632
current_seq = 1495
count = 40
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.086426/1485, current 535.197693/1495: elapsed=111259.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.186584
last_received_ts = 535.186523
last_seq = 1494
current_ts = 535.297852
current_received_ts = 535.298096
current_seq = 1504
count = 40
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.186584/1494, current 535.297852/1504: elapsed=111257.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.197693
last_received_ts = 535.197632
last_seq = 1495
current_ts = 535.308960
current_received_ts = 535.309204
current_seq = 1505
count = 41
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.197693/1495, current 535.308960/1505: elapsed=111256.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.297852
last_received_ts = 535.298096
last_seq = 1504
current_ts = 535.409119
current_received_ts = 535.409241
current_seq = 1514
count = 41
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.297852/1504, current 535.409119/1514: elapsed=111258.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.308960
last_received_ts = 535.309204
last_seq = 1505
current_ts = 535.420227
current_received_ts = 535.420410
current_seq = 1515
count = 42
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.308960/1505, current 535.420227/1515: elapsed=111259.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.409119
last_received_ts = 535.409241
last_seq = 1514
current_ts = 535.520386
current_received_ts = 535.520447
current_seq = 1524
count = 42
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.409119/1514, current 535.520386/1524: elapsed=111258.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.420227
last_received_ts = 535.420410
last_seq = 1515
current_ts = 535.531494
current_received_ts = 535.531555
current_seq = 1525
count = 43
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.420227/1515, current 535.531494/1525: elapsed=111262.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.520386
last_received_ts = 535.520447
last_seq = 1524
current_ts = 535.631592
current_received_ts = 535.631775
current_seq = 1534
count = 43
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.520386/1524, current 535.631592/1534: elapsed=111260.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.531494
last_received_ts = 535.531555
last_seq = 1525
current_ts = 535.642761
current_received_ts = 535.642944
current_seq = 1535
count = 44
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.531494/1525, current 535.642761/1535: elapsed=111254.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.631592
last_received_ts = 535.631775
last_seq = 1534
current_ts = 535.742859
current_received_ts = 535.742798
current_seq = 1544
count = 44
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.631592/1534, current 535.742859/1544: elapsed=111261.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.642761
last_received_ts = 535.642944
last_seq = 1535
current_ts = 535.754028
current_received_ts = 535.754211
current_seq = 1545
count = 45
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.642761/1535, current 535.754028/1545: elapsed=111258.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.742859
last_received_ts = 535.742798
last_seq = 1544
current_ts = 535.854126
current_received_ts = 535.854309
current_seq = 1554
count = 45
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.742859/1544, current 535.854126/1554: elapsed=111255.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.754028
last_received_ts = 535.754211
last_seq = 1545
current_ts = 535.865234
current_received_ts = 535.865417
current_seq = 1555
count = 46
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.754028/1545, current 535.865234/1555: elapsed=111254.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.854126
last_received_ts = 535.854309
last_seq = 1554
current_ts = 535.965393
current_received_ts = 535.965515
current_seq = 1564
count = 46
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.854126/1554, current 535.965393/1564: elapsed=111243.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.865234
last_received_ts = 535.865417
last_seq = 1555
current_ts = 535.976501
current_received_ts = 535.976685
current_seq = 1565
count = 47
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.865234/1555, current 535.976501/1565: elapsed=111247.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 535.965393
last_received_ts = 535.965515
last_seq = 1564
current_ts = 536.076599
current_received_ts = 536.076782
current_seq = 1574
count = 47
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 535.965393/1564, current 536.076599/1574: elapsed=111249.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 535.976501
last_received_ts = 535.976685
last_seq = 1565
current_ts = 536.087769
current_received_ts = 536.087830
current_seq = 1575
count = 48
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 535.976501/1565, current 536.087769/1575: elapsed=111250.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.076599
last_received_ts = 536.076782
last_seq = 1574
current_ts = 536.187866
current_received_ts = 536.188110
current_seq = 1584
count = 48
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.076599/1574, current 536.187866/1584: elapsed=111247.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.087769
last_received_ts = 536.087830
last_seq = 1575
current_ts = 536.198975
current_received_ts = 536.199158
current_seq = 1585
count = 49
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.087769/1575, current 536.198975/1585: elapsed=111244.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.187866
last_received_ts = 536.188110
last_seq = 1584
current_ts = 536.299133
current_received_ts = 536.299194
current_seq = 1594
count = 49
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.187866/1584, current 536.299133/1594: elapsed=111246.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.198975
last_received_ts = 536.199158
last_seq = 1585
current_ts = 536.310242
current_received_ts = 536.310303
current_seq = 1595
count = 50
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.198975/1585, current 536.310242/1595: elapsed=111249.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.299133
last_received_ts = 536.299194
last_seq = 1594
current_ts = 536.410339
current_received_ts = 536.410522
current_seq = 1604
count = 50
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.299133/1594, current 536.410339/1604: elapsed=111249.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.310242
last_received_ts = 536.310303
last_seq = 1595
current_ts = 536.421509
current_received_ts = 536.421692
current_seq = 1605
count = 51
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.310242/1595, current 536.421509/1605: elapsed=111245.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.410339
last_received_ts = 536.410522
last_seq = 1604
current_ts = 536.521606
current_received_ts = 536.521790
current_seq = 1614
count = 51
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.410339/1604, current 536.521606/1614: elapsed=111247.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.421509
last_received_ts = 536.421692
last_seq = 1605
current_ts = 536.532715
current_received_ts = 536.532654
current_seq = 1615
count = 52
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.421509/1605, current 536.532715/1615: elapsed=111248.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.521606
last_received_ts = 536.521790
last_seq = 1614
current_ts = 536.632874
current_received_ts = 536.633118
current_seq = 1624
count = 52
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.521606/1614, current 536.632874/1624: elapsed=111248.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.532715
last_received_ts = 536.532654
last_seq = 1615
current_ts = 536.643982
current_received_ts = 536.644165
current_seq = 1625
count = 53
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.532715/1615, current 536.643982/1625: elapsed=111249.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.632874
last_received_ts = 536.633118
last_seq = 1624
current_ts = 536.744080
current_received_ts = 536.744263
current_seq = 1634
count = 53
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.632874/1624, current 536.744080/1634: elapsed=111246.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.643982
last_received_ts = 536.644165
last_seq = 1625
current_ts = 536.755249
current_received_ts = 536.755371
current_seq = 1635
count = 54
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.643982/1625, current 536.755249/1635: elapsed=111246.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.744080
last_received_ts = 536.744263
last_seq = 1634
current_ts = 536.855347
current_received_ts = 536.855530
current_seq = 1644
count = 54
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.744080/1634, current 536.855347/1644: elapsed=111242.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.755249
last_received_ts = 536.755371
last_seq = 1635
current_ts = 536.866455
current_received_ts = 536.866638
current_seq = 1645
count = 55
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.755249/1635, current 536.866455/1645: elapsed=111242.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.855347
last_received_ts = 536.855530
last_seq = 1644
current_ts = 536.966614
current_received_ts = 536.966736
current_seq = 1654
count = 55
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.855347/1644, current 536.966614/1654: elapsed=111235.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.866455
last_received_ts = 536.866638
last_seq = 1645
current_ts = 536.977722
current_received_ts = 536.977905
current_seq = 1655
count = 56
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.866455/1645, current 536.977722/1655: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 536.966614
last_received_ts = 536.966736
last_seq = 1654
current_ts = 537.077820
current_received_ts = 537.077881
current_seq = 1664
count = 56
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 536.966614/1654, current 537.077820/1664: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 536.977722
last_received_ts = 536.977905
last_seq = 1655
current_ts = 537.088928
current_received_ts = 537.089111
current_seq = 1665
count = 57
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 536.977722/1655, current 537.088928/1665: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.077820
last_received_ts = 537.077881
last_seq = 1664
current_ts = 537.189087
current_received_ts = 537.189209
current_seq = 1674
count = 57
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.077820/1664, current 537.189087/1674: elapsed=111238.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.088928
last_received_ts = 537.089111
last_seq = 1665
current_ts = 537.200195
current_received_ts = 537.200378
current_seq = 1675
count = 58
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.088928/1665, current 537.200195/1675: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.189087
last_received_ts = 537.189209
last_seq = 1674
current_ts = 537.300293
current_received_ts = 537.300476
current_seq = 1684
count = 58
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.189087/1674, current 537.300293/1684: elapsed=111235.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.200195
last_received_ts = 537.200378
last_seq = 1675
current_ts = 537.311401
current_received_ts = 537.311340
current_seq = 1685
count = 59
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.200195/1675, current 537.311401/1685: elapsed=111238.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.300293
last_received_ts = 537.300476
last_seq = 1684
current_ts = 537.411560
current_received_ts = 537.411560
current_seq = 1694
count = 59
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.300293/1684, current 537.411560/1694: elapsed=111238.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.311401
last_received_ts = 537.311340
last_seq = 1685
current_ts = 537.422668
current_received_ts = 537.422852
current_seq = 1695
count = 60
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.311401/1685, current 537.422668/1695: elapsed=111237.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.411560
last_received_ts = 537.411560
last_seq = 1694
current_ts = 537.522766
current_received_ts = 537.522949
current_seq = 1704
count = 60
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.411560/1694, current 537.522766/1704: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.422668
last_received_ts = 537.422852
last_seq = 1695
current_ts = 537.533875
current_received_ts = 537.534119
current_seq = 1705
count = 61
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.422668/1695, current 537.533875/1705: elapsed=111237.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.522766
last_received_ts = 537.522949
last_seq = 1704
current_ts = 537.634033
current_received_ts = 537.634155
current_seq = 1714
count = 61
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.522766/1704, current 537.634033/1714: elapsed=111237.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.533875
last_received_ts = 537.534119
last_seq = 1705
current_ts = 537.645142
current_received_ts = 537.645264
current_seq = 1715
count = 62
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.533875/1705, current 537.645142/1715: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.634033
last_received_ts = 537.634155
last_seq = 1714
current_ts = 537.745239
current_received_ts = 537.745422
current_seq = 1724
count = 62
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.634033/1714, current 537.745239/1724: elapsed=111238.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.645142
last_received_ts = 537.645264
last_seq = 1715
current_ts = 537.756348
current_received_ts = 537.756531
current_seq = 1725
count = 63
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.645142/1715, current 537.756348/1725: elapsed=111236.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.745239
last_received_ts = 537.745422
last_seq = 1724
current_ts = 537.856506
current_received_ts = 537.856506
current_seq = 1734
count = 63
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.745239/1724, current 537.856506/1734: elapsed=111233.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.756348
last_received_ts = 537.756531
last_seq = 1725
current_ts = 537.867615
current_received_ts = 537.867798
current_seq = 1735
count = 64
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.756348/1725, current 537.867615/1735: elapsed=111232.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.856506
last_received_ts = 537.856506
last_seq = 1734
current_ts = 537.967712
current_received_ts = 537.967834
current_seq = 1744
count = 64
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.856506/1734, current 537.967712/1744: elapsed=111227.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.867615
last_received_ts = 537.867798
last_seq = 1735
current_ts = 537.978821
current_received_ts = 537.979065
current_seq = 1745
count = 65
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.867615/1735, current 537.978821/1745: elapsed=111231.0us expected=110953.1us +- 554.8us, error 0.3%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 537.967712
last_received_ts = 537.967834
last_seq = 1744
current_ts = 538.078918
current_received_ts = 538.079163
current_seq = 1754
count = 65
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 537.967712/1744, current 538.078918/1754: elapsed=111228.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 537.978821
last_received_ts = 537.979065
last_seq = 1745
current_ts = 538.090027
current_received_ts = 538.090210
current_seq = 1755
count = 66
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 537.978821/1745, current 538.090027/1755: elapsed=111226.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 538.078918
last_received_ts = 538.079163
last_seq = 1754
current_ts = 538.190186
current_received_ts = 538.190369
current_seq = 1764
count = 66
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 538.078918/1754, current 538.190186/1764: elapsed=111228.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: name = flip
last_ts = 538.090027
last_received_ts = 538.090210
last_seq = 1755
current_ts = 538.201294
current_received_ts = 538.201477
current_seq = 1765
count = 67
seq_step = 1
(kms_flip:2760) DEBUG: flip ts/seq: last 538.090027/1755, current 538.201294/1765: elapsed=111223.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: name = vblank
last_ts = 538.190186
last_received_ts = 538.190369
last_seq = 1764
current_ts = 538.301392
current_received_ts = 538.301514
current_seq = 1774
count = 67
seq_step = 10
(kms_flip:2760) DEBUG: vblank ts/seq: last 538.190186/1764, current 538.301392/1774: elapsed=111225.0us expected=110953.1us +- 554.8us, error 0.2%
(kms_flip:2760) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2760) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2760) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2760) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2760) igt_core-INFO: Stack trace:
(kms_flip:2760) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2760) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2760) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2760) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2760) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2760) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2760) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2760) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-eDP1: FAIL (12.443s)
Subtest flip-vs-absolute-wf_vblank: FAIL (39.017s)
(kms_flip:2760) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2234:
(kms_flip:2760) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2760) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2760) igt_kms-CRITICAL: DPMS property not found on 241