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

shard-mtlp-4

IGT-Version: 1.30-gb6b9fa1a0 (x86_64) (Linux: 6.14.0-rc4-CI_DRM_16202-g4e4a83bc30b7+ x86_64)

Using IGT_SRANDOM=1740789800 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 10812.3us +- 4.012us accuracy 0.11%
vblank interval differs from modeline! expected 11111.1us, measured 10812us +- 4.012us, difference 298.8us (74.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (6.266s)
Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 10974.2us +- 2.857us accuracy 0.08%
vblank interval differs from modeline! expected 11111.1us, measured 10974us +- 2.857us, difference 136.9us (47.9 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (9.224s)
Starting dynamic subtest: C-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11066.0us +- 2.338us accuracy 0.06%
vblank interval differs from modeline! expected 11111.1us, measured 11066us +- 2.338us, difference 45.1us (19.3 sigma)
Dynamic subtest C-eDP1: SUCCESS (8.930s)
Starting dynamic subtest: D-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11093.6us +- 2.941us accuracy 0.08%
vblank interval differs from modeline! expected 11111.1us, measured 11094us +- 2.941us, difference 17.5us (6.0 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-eDP1: FAIL (12.088s)
Subtest flip-vs-absolute-wf_vblank: FAIL (36.515s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 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:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=11520)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_kms-INFO:   2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
(kms_flip:2540) DEBUG: No stale events found
(kms_flip:2540) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2540) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2540) INFO: Expected frametime: 11111us; measured 10812.3us +- 4.012us accuracy 0.11%
(kms_flip:2540) INFO: vblank interval differs from modeline! expected 11111.1us, measured 10812us +- 4.012us, difference 298.8us (74.5 sigma)
(kms_flip:2540) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 174.742538
current_received_ts = 174.742310
current_seq = 6139
count = 0
seq_step = 1
(kms_flip:2540) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 174.839859
current_received_ts = 174.839798
current_seq = 6148
count = 0
seq_step = 10
(kms_flip:2540) DEBUG: name = flip
last_ts = 174.742538
last_received_ts = 174.742310
last_seq = 6139
current_ts = 174.850677
current_received_ts = 174.850540
current_seq = 6149
count = 1
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 174.742538/6139, current 174.850677/6149: elapsed=108130.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 174.839859
last_received_ts = 174.839798
last_seq = 6148
current_ts = 174.947983
current_received_ts = 174.947922
current_seq = 6158
count = 1
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 174.839859/6148, current 174.947983/6158: elapsed=108125.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 174.850677
last_received_ts = 174.850540
last_seq = 6149
current_ts = 174.958801
current_received_ts = 174.958725
current_seq = 6159
count = 2
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 174.850677/6149, current 174.958801/6159: elapsed=108124.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 174.947983
last_received_ts = 174.947922
last_seq = 6158
current_ts = 175.056107
current_received_ts = 175.056274
current_seq = 6168
count = 2
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 174.947983/6158, current 175.056107/6168: elapsed=108126.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 174.958801
last_received_ts = 174.958725
last_seq = 6159
current_ts = 175.066925
current_received_ts = 175.066864
current_seq = 6169
count = 3
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 174.958801/6159, current 175.066925/6169: elapsed=108125.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.056107
last_received_ts = 175.056274
last_seq = 6168
current_ts = 175.164230
current_received_ts = 175.164383
current_seq = 6178
count = 3
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.056107/6168, current 175.164230/6178: elapsed=108124.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.066925
last_received_ts = 175.066864
last_seq = 6169
current_ts = 175.175049
current_received_ts = 175.175232
current_seq = 6179
count = 4
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.066925/6169, current 175.175049/6179: elapsed=108125.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.164230
last_received_ts = 175.164383
last_seq = 6178
current_ts = 175.272369
current_received_ts = 175.272186
current_seq = 6188
count = 4
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.164230/6178, current 175.272369/6188: elapsed=108135.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.175049
last_received_ts = 175.175232
last_seq = 6179
current_ts = 175.283188
current_received_ts = 175.283096
current_seq = 6189
count = 5
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.175049/6179, current 175.283188/6189: elapsed=108133.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.272369
last_received_ts = 175.272186
last_seq = 6188
current_ts = 175.380508
current_received_ts = 175.380630
current_seq = 6198
count = 5
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.272369/6188, current 175.380508/6198: elapsed=108145.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.283188
last_received_ts = 175.283096
last_seq = 6189
current_ts = 175.391357
current_received_ts = 175.391525
current_seq = 6199
count = 6
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.283188/6189, current 175.391357/6199: elapsed=108177.0us expected=108123.1us +- 540.6us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.380508
last_received_ts = 175.380630
last_seq = 6198
current_ts = 175.489014
current_received_ts = 175.488998
current_seq = 6208
count = 6
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.380508/6198, current 175.489014/6208: elapsed=108494.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.391357
last_received_ts = 175.391525
last_seq = 6199
current_ts = 175.499863
current_received_ts = 175.499832
current_seq = 6209
count = 7
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.391357/6199, current 175.499863/6209: elapsed=108501.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.489014
last_received_ts = 175.488998
last_seq = 6208
current_ts = 175.597504
current_received_ts = 175.597641
current_seq = 6218
count = 7
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.489014/6208, current 175.597504/6218: elapsed=108493.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.499863
last_received_ts = 175.499832
last_seq = 6209
current_ts = 175.608353
current_received_ts = 175.608490
current_seq = 6219
count = 8
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.499863/6209, current 175.608353/6219: elapsed=108490.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.597504
last_received_ts = 175.597641
last_seq = 6218
current_ts = 175.705994
current_received_ts = 175.706329
current_seq = 6228
count = 8
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.597504/6218, current 175.705994/6228: elapsed=108491.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.608353
last_received_ts = 175.608490
last_seq = 6219
current_ts = 175.716843
current_received_ts = 175.716888
current_seq = 6229
count = 9
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.608353/6219, current 175.716843/6229: elapsed=108495.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.705994
last_received_ts = 175.706329
last_seq = 6228
current_ts = 175.814499
current_received_ts = 175.814362
current_seq = 6238
count = 9
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.705994/6228, current 175.814499/6238: elapsed=108503.0us expected=108123.1us +- 540.6us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.716843
last_received_ts = 175.716888
last_seq = 6229
current_ts = 175.825333
current_received_ts = 175.825470
current_seq = 6239
count = 10
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.716843/6229, current 175.825333/6239: elapsed=108493.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.814499
last_received_ts = 175.814362
last_seq = 6238
current_ts = 175.922974
current_received_ts = 175.923172
current_seq = 6248
count = 10
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.814499/6238, current 175.922974/6248: elapsed=108486.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.825333
last_received_ts = 175.825470
last_seq = 6239
current_ts = 175.933838
current_received_ts = 175.933762
current_seq = 6249
count = 11
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.825333/6239, current 175.933838/6249: elapsed=108498.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 175.922974
last_received_ts = 175.923172
last_seq = 6248
current_ts = 176.031479
current_received_ts = 176.031647
current_seq = 6258
count = 11
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 175.922974/6248, current 176.031479/6258: elapsed=108494.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 175.933838
last_received_ts = 175.933762
last_seq = 6249
current_ts = 176.042328
current_received_ts = 176.042130
current_seq = 6259
count = 12
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 175.933838/6249, current 176.042328/6259: elapsed=108495.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 176.031479
last_received_ts = 176.031647
last_seq = 6258
current_ts = 176.139969
current_received_ts = 176.140305
current_seq = 6268
count = 12
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 176.031479/6258, current 176.139969/6268: elapsed=108493.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 176.042328
last_received_ts = 176.042130
last_seq = 6259
current_ts = 176.150818
current_received_ts = 176.150803
current_seq = 6269
count = 13
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 176.042328/6259, current 176.150818/6269: elapsed=108489.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 176.139969
last_received_ts = 176.140305
last_seq = 6268
current_ts = 176.248474
current_received_ts = 176.248367
current_seq = 6278
count = 13
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 176.139969/6268, current 176.248474/6278: elapsed=108502.0us expected=108123.1us +- 540.6us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 176.150818
last_received_ts = 176.150803
last_seq = 6269
current_ts = 176.259308
current_received_ts = 176.259186
current_seq = 6279
count = 14
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 176.150818/6269, current 176.259308/6279: elapsed=108495.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 176.248474
last_received_ts = 176.248367
last_seq = 6278
current_ts = 176.356964
current_received_ts = 176.357117
current_seq = 6288
count = 14
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 176.248474/6278, current 176.356964/6288: elapsed=108488.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 176.259308
last_received_ts = 176.259186
last_seq = 6279
current_ts = 176.367813
current_received_ts = 176.367844
current_seq = 6289
count = 15
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 176.259308/6279, current 176.367813/6289: elapsed=108497.0us expected=108123.1us +- 540.6us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 176.356964
last_received_ts = 176.357117
last_seq = 6288
current_ts = 176.465714
current_received_ts = 176.465912
current_seq = 6298
count = 15
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 176.356964/6288, current 176.465714/6298: elapsed=108759.0us expected=108123.1us +- 540.6us, error 0.6%
(kms_flip:2540) DEBUG: inconsistent vblank ts/seq: last 176.356964/6288, current 176.465714/6298: elapsed=108759.0us expected=108123.1us
(kms_flip:2540) DEBUG: expected 103694, counted 150, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 103694, counted 150, encoder type 2
(kms_flip:2540) DEBUG: expected 103694, counted 150, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 103694, counted 150, encoder type 2
(kms_flip:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2540) igt_core-INFO: Stack trace:
(kms_flip:2540) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2540) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2540) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2540) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2540) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2540) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2540) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2540) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (6.266s)
Starting dynamic subtest: B-eDP1
(kms_flip:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=11520)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=2880, height=1800, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2540) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=8, pitch=11520)
(kms_flip:2540) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2540) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2540) igt_kms-INFO:   2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
(kms_flip:2540) DEBUG: No stale events found
(kms_flip:2540) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2540) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2540) INFO: Expected frametime: 11111us; measured 10974.2us +- 2.857us accuracy 0.08%
(kms_flip:2540) INFO: vblank interval differs from modeline! expected 11111.1us, measured 10974us +- 2.857us, difference 136.9us (47.9 sigma)
(kms_flip:2540) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 180.844711
current_received_ts = 180.844513
current_seq = 268
count = 0
seq_step = 1
(kms_flip:2540) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 180.943481
current_received_ts = 180.943649
current_seq = 277
count = 0
seq_step = 10
(kms_flip:2540) DEBUG: name = flip
last_ts = 180.844711
last_received_ts = 180.844513
last_seq = 268
current_ts = 180.954453
current_received_ts = 180.954361
current_seq = 278
count = 1
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 180.844711/268, current 180.954453/278: elapsed=109738.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 180.943481
last_received_ts = 180.943649
last_seq = 277
current_ts = 181.053207
current_received_ts = 181.053375
current_seq = 287
count = 1
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 180.943481/277, current 181.053207/287: elapsed=109737.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 180.954453
last_received_ts = 180.954361
last_seq = 278
current_ts = 181.064194
current_received_ts = 181.064087
current_seq = 288
count = 2
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 180.954453/278, current 181.064194/288: elapsed=109742.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.053207
last_received_ts = 181.053375
last_seq = 287
current_ts = 181.162949
current_received_ts = 181.162857
current_seq = 297
count = 2
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.053207/287, current 181.162949/297: elapsed=109744.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.064194
last_received_ts = 181.064087
last_seq = 288
current_ts = 181.173935
current_received_ts = 181.173859
current_seq = 298
count = 3
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.064194/288, current 181.173935/298: elapsed=109741.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.162949
last_received_ts = 181.162857
last_seq = 297
current_ts = 181.272690
current_received_ts = 181.272949
current_seq = 307
count = 3
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.162949/297, current 181.272690/307: elapsed=109741.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.173935
last_received_ts = 181.173859
last_seq = 298
current_ts = 181.283676
current_received_ts = 181.283554
current_seq = 308
count = 4
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.173935/298, current 181.283676/308: elapsed=109746.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.272690
last_received_ts = 181.272949
last_seq = 307
current_ts = 181.382446
current_received_ts = 181.382385
current_seq = 317
count = 4
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.272690/307, current 181.382446/317: elapsed=109754.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.283676
last_received_ts = 181.283554
last_seq = 308
current_ts = 181.393448
current_received_ts = 181.393250
current_seq = 318
count = 5
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.283676/308, current 181.393448/318: elapsed=109769.0us expected=109741.9us +- 548.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.382446
last_received_ts = 181.382385
last_seq = 317
current_ts = 181.492355
current_received_ts = 181.492508
current_seq = 327
count = 5
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.382446/317, current 181.492355/327: elapsed=109904.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.393448
last_received_ts = 181.393250
last_seq = 318
current_ts = 181.503342
current_received_ts = 181.503540
current_seq = 328
count = 6
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.393448/318, current 181.503342/328: elapsed=109906.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.492355
last_received_ts = 181.492508
last_seq = 327
current_ts = 181.602264
current_received_ts = 181.602097
current_seq = 337
count = 6
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.492355/327, current 181.602264/337: elapsed=109911.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.503342
last_received_ts = 181.503540
last_seq = 328
current_ts = 181.613251
current_received_ts = 181.613144
current_seq = 338
count = 7
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.503342/328, current 181.613251/338: elapsed=109904.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.602264
last_received_ts = 181.602097
last_seq = 337
current_ts = 181.712173
current_received_ts = 181.712158
current_seq = 347
count = 7
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.602264/337, current 181.712173/347: elapsed=109905.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.613251
last_received_ts = 181.613144
last_seq = 338
current_ts = 181.723160
current_received_ts = 181.723129
current_seq = 348
count = 8
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.613251/338, current 181.723160/348: elapsed=109906.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.712173
last_received_ts = 181.712158
last_seq = 347
current_ts = 181.822067
current_received_ts = 181.822220
current_seq = 357
count = 8
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.712173/347, current 181.822067/357: elapsed=109902.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.723160
last_received_ts = 181.723129
last_seq = 348
current_ts = 181.833069
current_received_ts = 181.833054
current_seq = 358
count = 9
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.723160/348, current 181.833069/358: elapsed=109905.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.822067
last_received_ts = 181.822220
last_seq = 357
current_ts = 181.931976
current_received_ts = 181.932159
current_seq = 367
count = 9
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.822067/357, current 181.931976/367: elapsed=109907.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.833069
last_received_ts = 181.833054
last_seq = 358
current_ts = 181.942978
current_received_ts = 181.942917
current_seq = 368
count = 10
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.833069/358, current 181.942978/368: elapsed=109911.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 181.931976
last_received_ts = 181.932159
last_seq = 367
current_ts = 182.041885
current_received_ts = 182.041992
current_seq = 377
count = 10
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 181.931976/367, current 182.041885/377: elapsed=109909.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 181.942978
last_received_ts = 181.942917
last_seq = 368
current_ts = 182.052872
current_received_ts = 182.052811
current_seq = 378
count = 11
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 181.942978/368, current 182.052872/378: elapsed=109903.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.041885
last_received_ts = 182.041992
last_seq = 377
current_ts = 182.151794
current_received_ts = 182.151947
current_seq = 387
count = 11
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.041885/377, current 182.151794/387: elapsed=109907.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.052872
last_received_ts = 182.052811
last_seq = 378
current_ts = 182.162781
current_received_ts = 182.162689
current_seq = 388
count = 12
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.052872/378, current 182.162781/388: elapsed=109907.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.151794
last_received_ts = 182.151947
last_seq = 387
current_ts = 182.261703
current_received_ts = 182.261597
current_seq = 397
count = 12
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.151794/387, current 182.261703/397: elapsed=109905.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.162781
last_received_ts = 182.162689
last_seq = 388
current_ts = 182.272690
current_received_ts = 182.272614
current_seq = 398
count = 13
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.162781/388, current 182.272690/398: elapsed=109907.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.261703
last_received_ts = 182.261597
last_seq = 397
current_ts = 182.371613
current_received_ts = 182.371704
current_seq = 407
count = 13
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.261703/397, current 182.371613/407: elapsed=109905.0us expected=109741.9us +- 548.7us, error 0.1%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.272690
last_received_ts = 182.272614
last_seq = 398
current_ts = 182.382614
current_received_ts = 182.382431
current_seq = 408
count = 14
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.272690/398, current 182.382614/408: elapsed=109918.0us expected=109741.9us +- 548.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.371613
last_received_ts = 182.371704
last_seq = 407
current_ts = 182.481659
current_received_ts = 182.481796
current_seq = 417
count = 14
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.371613/407, current 182.481659/417: elapsed=110047.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.382614
last_received_ts = 182.382431
last_seq = 408
current_ts = 182.492661
current_received_ts = 182.492523
current_seq = 418
count = 15
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.382614/408, current 182.492661/418: elapsed=110049.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.481659
last_received_ts = 182.481796
last_seq = 417
current_ts = 182.591705
current_received_ts = 182.591934
current_seq = 427
count = 15
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.481659/417, current 182.591705/427: elapsed=110050.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.492661
last_received_ts = 182.492523
last_seq = 418
current_ts = 182.602707
current_received_ts = 182.602539
current_seq = 428
count = 16
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.492661/418, current 182.602707/428: elapsed=110049.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.591705
last_received_ts = 182.591934
last_seq = 427
current_ts = 182.701752
current_received_ts = 182.701981
current_seq = 437
count = 16
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.591705/427, current 182.701752/437: elapsed=110046.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.602707
last_received_ts = 182.602539
last_seq = 428
current_ts = 182.712753
current_received_ts = 182.712692
current_seq = 438
count = 17
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.602707/428, current 182.712753/438: elapsed=110048.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.701752
last_received_ts = 182.701981
last_seq = 437
current_ts = 182.811798
current_received_ts = 182.811966
current_seq = 447
count = 17
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.701752/437, current 182.811798/447: elapsed=110051.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.712753
last_received_ts = 182.712692
last_seq = 438
current_ts = 182.822815
current_received_ts = 182.822723
current_seq = 448
count = 18
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.712753/438, current 182.822815/448: elapsed=110052.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.811798
last_received_ts = 182.811966
last_seq = 447
current_ts = 182.921844
current_received_ts = 182.922104
current_seq = 457
count = 18
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.811798/447, current 182.921844/457: elapsed=110051.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.822815
last_received_ts = 182.822723
last_seq = 448
current_ts = 182.932861
current_received_ts = 182.932816
current_seq = 458
count = 19
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.822815/448, current 182.932861/458: elapsed=110050.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 182.921844
last_received_ts = 182.922104
last_seq = 457
current_ts = 183.031906
current_received_ts = 183.032104
current_seq = 467
count = 19
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 182.921844/457, current 183.031906/467: elapsed=110053.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 182.932861
last_received_ts = 182.932816
last_seq = 458
current_ts = 183.042908
current_received_ts = 183.043076
current_seq = 468
count = 20
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 182.932861/458, current 183.042908/468: elapsed=110048.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.031906
last_received_ts = 183.032104
last_seq = 467
current_ts = 183.141953
current_received_ts = 183.142136
current_seq = 477
count = 20
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.031906/467, current 183.141953/477: elapsed=110045.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.042908
last_received_ts = 183.043076
last_seq = 468
current_ts = 183.152954
current_received_ts = 183.152924
current_seq = 478
count = 21
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.042908/468, current 183.152954/478: elapsed=110051.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.141953
last_received_ts = 183.142136
last_seq = 477
current_ts = 183.251999
current_received_ts = 183.252136
current_seq = 487
count = 21
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.141953/477, current 183.251999/487: elapsed=110051.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.152954
last_received_ts = 183.152924
last_seq = 478
current_ts = 183.263016
current_received_ts = 183.262817
current_seq = 488
count = 22
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.152954/478, current 183.263016/488: elapsed=110053.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.251999
last_received_ts = 183.252136
last_seq = 487
current_ts = 183.362045
current_received_ts = 183.362289
current_seq = 497
count = 22
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.251999/487, current 183.362045/497: elapsed=110052.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.263016
last_received_ts = 183.262817
last_seq = 488
current_ts = 183.373062
current_received_ts = 183.372894
current_seq = 498
count = 23
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.263016/488, current 183.373062/498: elapsed=110047.0us expected=109741.9us +- 548.7us, error 0.3%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.362045
last_received_ts = 183.362289
last_seq = 497
current_ts = 183.472214
current_received_ts = 183.472382
current_seq = 507
count = 23
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.362045/497, current 183.472214/507: elapsed=110161.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.373062
last_received_ts = 183.372894
last_seq = 498
current_ts = 183.483231
current_received_ts = 183.483109
current_seq = 508
count = 24
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.373062/498, current 183.483231/508: elapsed=110176.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.472214
last_received_ts = 183.472382
last_seq = 507
current_ts = 183.582382
current_received_ts = 183.582642
current_seq = 517
count = 24
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.472214/507, current 183.582382/517: elapsed=110171.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.483231
last_received_ts = 183.483109
last_seq = 508
current_ts = 183.593399
current_received_ts = 183.593262
current_seq = 518
count = 25
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.483231/508, current 183.593399/518: elapsed=110171.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.582382
last_received_ts = 183.582642
last_seq = 517
current_ts = 183.692566
current_received_ts = 183.692642
current_seq = 527
count = 25
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.582382/517, current 183.692566/527: elapsed=110177.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.593399
last_received_ts = 183.593262
last_seq = 518
current_ts = 183.703583
current_received_ts = 183.703384
current_seq = 528
count = 26
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.593399/518, current 183.703583/528: elapsed=110176.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.692566
last_received_ts = 183.692642
last_seq = 527
current_ts = 183.802734
current_received_ts = 183.802643
current_seq = 537
count = 26
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.692566/527, current 183.802734/537: elapsed=110177.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.703583
last_received_ts = 183.703384
last_seq = 528
current_ts = 183.813751
current_received_ts = 183.813538
current_seq = 538
count = 27
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.703583/528, current 183.813751/538: elapsed=110175.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.802734
last_received_ts = 183.802643
last_seq = 537
current_ts = 183.912918
current_received_ts = 183.913193
current_seq = 547
count = 27
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.802734/537, current 183.912918/547: elapsed=110177.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.813751
last_received_ts = 183.813538
last_seq = 538
current_ts = 183.923935
current_received_ts = 183.923767
current_seq = 548
count = 28
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.813751/538, current 183.923935/548: elapsed=110179.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 183.912918
last_received_ts = 183.913193
last_seq = 547
current_ts = 184.023087
current_received_ts = 184.023254
current_seq = 557
count = 28
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 183.912918/547, current 184.023087/557: elapsed=110177.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 183.923935
last_received_ts = 183.923767
last_seq = 548
current_ts = 184.034103
current_received_ts = 184.033890
current_seq = 558
count = 29
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 183.923935/548, current 184.034103/558: elapsed=110172.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.023087
last_received_ts = 184.023254
last_seq = 557
current_ts = 184.133270
current_received_ts = 184.133392
current_seq = 567
count = 29
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.023087/557, current 184.133270/567: elapsed=110172.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.034103
last_received_ts = 184.033890
last_seq = 558
current_ts = 184.144287
current_received_ts = 184.144073
current_seq = 568
count = 30
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.034103/558, current 184.144287/568: elapsed=110178.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.133270
last_received_ts = 184.133392
last_seq = 567
current_ts = 184.243439
current_received_ts = 184.243271
current_seq = 577
count = 30
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.133270/567, current 184.243439/577: elapsed=110180.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.144287
last_received_ts = 184.144073
last_seq = 568
current_ts = 184.254456
current_received_ts = 184.254288
current_seq = 578
count = 31
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.144287/568, current 184.254456/578: elapsed=110175.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.243439
last_received_ts = 184.243271
last_seq = 577
current_ts = 184.353607
current_received_ts = 184.353775
current_seq = 587
count = 31
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.243439/577, current 184.353607/587: elapsed=110171.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.254456
last_received_ts = 184.254288
last_seq = 578
current_ts = 184.364639
current_received_ts = 184.364441
current_seq = 588
count = 32
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.254456/578, current 184.364639/588: elapsed=110173.0us expected=109741.9us +- 548.7us, error 0.4%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.353607
last_received_ts = 184.353775
last_seq = 587
current_ts = 184.463882
current_received_ts = 184.464157
current_seq = 597
count = 32
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.353607/587, current 184.463882/597: elapsed=110269.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.364639
last_received_ts = 184.364441
last_seq = 588
current_ts = 184.474915
current_received_ts = 184.474701
current_seq = 598
count = 33
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.364639/588, current 184.474915/598: elapsed=110279.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.463882
last_received_ts = 184.464157
last_seq = 597
current_ts = 184.574158
current_received_ts = 184.574295
current_seq = 607
count = 33
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.463882/597, current 184.574158/607: elapsed=110282.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.474915
last_received_ts = 184.474701
last_seq = 598
current_ts = 184.585190
current_received_ts = 184.585114
current_seq = 608
count = 34
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.474915/598, current 184.585190/608: elapsed=110284.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.574158
last_received_ts = 184.574295
last_seq = 607
current_ts = 184.684448
current_received_ts = 184.684601
current_seq = 617
count = 34
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.574158/607, current 184.684448/617: elapsed=110285.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.585190
last_received_ts = 184.585114
last_seq = 608
current_ts = 184.695480
current_received_ts = 184.695267
current_seq = 618
count = 35
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.585190/608, current 184.695480/618: elapsed=110287.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.684448
last_received_ts = 184.684601
last_seq = 617
current_ts = 184.794739
current_received_ts = 184.794952
current_seq = 627
count = 35
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.684448/617, current 184.794739/627: elapsed=110285.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.695480
last_received_ts = 184.695267
last_seq = 618
current_ts = 184.805771
current_received_ts = 184.805588
current_seq = 628
count = 36
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.695480/618, current 184.805771/628: elapsed=110286.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.794739
last_received_ts = 184.794952
last_seq = 627
current_ts = 184.905029
current_received_ts = 184.905228
current_seq = 637
count = 36
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.794739/627, current 184.905029/637: elapsed=110287.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.805771
last_received_ts = 184.805588
last_seq = 628
current_ts = 184.916061
current_received_ts = 184.915863
current_seq = 638
count = 37
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.805771/628, current 184.916061/638: elapsed=110286.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 184.905029
last_received_ts = 184.905228
last_seq = 637
current_ts = 185.015305
current_received_ts = 185.015457
current_seq = 647
count = 37
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 184.905029/637, current 185.015305/647: elapsed=110286.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 184.916061
last_received_ts = 184.915863
last_seq = 638
current_ts = 185.026337
current_received_ts = 185.026184
current_seq = 648
count = 38
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 184.916061/638, current 185.026337/648: elapsed=110286.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 185.015305
last_received_ts = 185.015457
last_seq = 647
current_ts = 185.125595
current_received_ts = 185.125732
current_seq = 657
count = 38
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 185.015305/647, current 185.125595/657: elapsed=110288.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 185.026337
last_received_ts = 185.026184
last_seq = 648
current_ts = 185.136627
current_received_ts = 185.136444
current_seq = 658
count = 39
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 185.026337/648, current 185.136627/658: elapsed=110283.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 185.125595
last_received_ts = 185.125732
last_seq = 657
current_ts = 185.235886
current_received_ts = 185.236130
current_seq = 667
count = 39
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 185.125595/657, current 185.235886/667: elapsed=110285.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 185.136627
last_received_ts = 185.136444
last_seq = 658
current_ts = 185.246902
current_received_ts = 185.246750
current_seq = 668
count = 40
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 185.136627/658, current 185.246902/668: elapsed=110287.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 185.235886
last_received_ts = 185.236130
last_seq = 667
current_ts = 185.346161
current_received_ts = 185.346344
current_seq = 677
count = 40
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 185.235886/667, current 185.346161/677: elapsed=110283.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = flip
last_ts = 185.246902
last_received_ts = 185.246750
last_seq = 668
current_ts = 185.357193
current_received_ts = 185.357040
current_seq = 678
count = 41
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 185.246902/668, current 185.357193/678: elapsed=110288.0us expected=109741.9us +- 548.7us, error 0.5%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 185.346161
last_received_ts = 185.346344
last_seq = 677
current_ts = 185.456528
current_received_ts = 185.456741
current_seq = 687
count = 41
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 185.346161/677, current 185.456528/687: elapsed=110358.0us expected=109741.9us +- 548.7us, error 0.6%
(kms_flip:2540) DEBUG: inconsistent vblank ts/seq: last 185.346161/677, current 185.456528/687: elapsed=110358.0us expected=109741.9us
(kms_flip:2540) DEBUG: expected 102164, counted 410, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 102164, counted 410, encoder type 2
(kms_flip:2540) DEBUG: expected 102164, counted 410, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 102164, counted 410, encoder type 2
(kms_flip:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2540) igt_core-INFO: Stack trace:
(kms_flip:2540) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2540) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2540) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2540) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2540) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2540) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2540) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2540) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.224s)
Starting dynamic subtest: C-eDP1
Dynamic subtest C-eDP1: SUCCESS (8.930s)
Starting dynamic subtest: D-eDP1
(kms_flip:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest D-eDP1 failed.
**** DEBUG ****
(kms_flip:2540) DEBUG: name = flip
last_ts = 199.676147
last_received_ts = 199.676071
last_seq = 364
current_ts = 199.787109
current_received_ts = 199.787170
current_seq = 374
count = 8
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 199.676147/364, current 199.787109/374: elapsed=110963.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 199.776016
last_received_ts = 199.776154
last_seq = 373
current_ts = 199.886978
current_received_ts = 199.886963
current_seq = 383
count = 8
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 199.776016/373, current 199.886978/383: elapsed=110965.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 199.787109
last_received_ts = 199.787170
last_seq = 374
current_ts = 199.898071
current_received_ts = 199.898224
current_seq = 384
count = 9
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 199.787109/374, current 199.898071/384: elapsed=110968.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 199.886978
last_received_ts = 199.886963
last_seq = 383
current_ts = 199.997940
current_received_ts = 199.998093
current_seq = 393
count = 9
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 199.886978/383, current 199.997940/393: elapsed=110967.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 199.898071
last_received_ts = 199.898224
last_seq = 384
current_ts = 200.009048
current_received_ts = 200.008942
current_seq = 394
count = 10
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 199.898071/384, current 200.009048/394: elapsed=110970.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 199.997940
last_received_ts = 199.998093
last_seq = 393
current_ts = 200.108917
current_received_ts = 200.108994
current_seq = 403
count = 10
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 199.997940/393, current 200.108917/403: elapsed=110967.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.009048
last_received_ts = 200.008942
last_seq = 394
current_ts = 200.120010
current_received_ts = 200.119965
current_seq = 404
count = 11
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.009048/394, current 200.120010/404: elapsed=110968.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.108917
last_received_ts = 200.108994
last_seq = 403
current_ts = 200.219879
current_received_ts = 200.219986
current_seq = 413
count = 11
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.108917/403, current 200.219879/413: elapsed=110971.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.120010
last_received_ts = 200.119965
last_seq = 404
current_ts = 200.230972
current_received_ts = 200.230865
current_seq = 414
count = 12
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.120010/404, current 200.230972/414: elapsed=110965.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.219879
last_received_ts = 200.219986
last_seq = 413
current_ts = 200.330841
current_received_ts = 200.330795
current_seq = 423
count = 12
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.219879/413, current 200.330841/423: elapsed=110966.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.230972
last_received_ts = 200.230865
last_seq = 414
current_ts = 200.341949
current_received_ts = 200.341766
current_seq = 424
count = 13
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.230972/414, current 200.341949/424: elapsed=110970.0us expected=110936.2us +- 554.7us, error 0.0%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.330841
last_received_ts = 200.330795
last_seq = 423
current_ts = 200.441956
current_received_ts = 200.442169
current_seq = 433
count = 13
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.330841/423, current 200.441956/433: elapsed=111111.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.341949
last_received_ts = 200.341766
last_seq = 424
current_ts = 200.453079
current_received_ts = 200.453064
current_seq = 434
count = 14
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.341949/424, current 200.453079/434: elapsed=111134.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.441956
last_received_ts = 200.442169
last_seq = 433
current_ts = 200.553162
current_received_ts = 200.553375
current_seq = 443
count = 14
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.441956/433, current 200.553162/443: elapsed=111208.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.453079
last_received_ts = 200.453064
last_seq = 434
current_ts = 200.564285
current_received_ts = 200.564133
current_seq = 444
count = 15
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.453079/434, current 200.564285/444: elapsed=111206.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.553162
last_received_ts = 200.553375
last_seq = 443
current_ts = 200.664368
current_received_ts = 200.664551
current_seq = 453
count = 15
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.553162/443, current 200.664368/453: elapsed=111203.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.564285
last_received_ts = 200.564133
last_seq = 444
current_ts = 200.675491
current_received_ts = 200.675400
current_seq = 454
count = 16
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.564285/444, current 200.675491/454: elapsed=111203.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.664368
last_received_ts = 200.664551
last_seq = 453
current_ts = 200.775574
current_received_ts = 200.775772
current_seq = 463
count = 16
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.664368/453, current 200.775574/463: elapsed=111207.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.675491
last_received_ts = 200.675400
last_seq = 454
current_ts = 200.786697
current_received_ts = 200.786530
current_seq = 464
count = 17
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.675491/454, current 200.786697/464: elapsed=111208.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.775574
last_received_ts = 200.775772
last_seq = 463
current_ts = 200.886780
current_received_ts = 200.886658
current_seq = 473
count = 17
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.775574/463, current 200.886780/473: elapsed=111206.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.786697
last_received_ts = 200.786530
last_seq = 464
current_ts = 200.897903
current_received_ts = 200.897842
current_seq = 474
count = 18
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.786697/464, current 200.897903/474: elapsed=111202.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.886780
last_received_ts = 200.886658
last_seq = 473
current_ts = 200.997986
current_received_ts = 200.998184
current_seq = 483
count = 18
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.886780/473, current 200.997986/483: elapsed=111206.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 200.897903
last_received_ts = 200.897842
last_seq = 474
current_ts = 201.009109
current_received_ts = 201.009094
current_seq = 484
count = 19
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 200.897903/474, current 201.009109/484: elapsed=111207.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 200.997986
last_received_ts = 200.998184
last_seq = 483
current_ts = 201.109192
current_received_ts = 201.109314
current_seq = 493
count = 19
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 200.997986/483, current 201.109192/493: elapsed=111202.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.009109
last_received_ts = 201.009094
last_seq = 484
current_ts = 201.120316
current_received_ts = 201.120209
current_seq = 494
count = 20
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.009109/484, current 201.120316/494: elapsed=111202.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.109192
last_received_ts = 201.109314
last_seq = 493
current_ts = 201.220398
current_received_ts = 201.220551
current_seq = 503
count = 20
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.109192/493, current 201.220398/503: elapsed=111207.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.120316
last_received_ts = 201.120209
last_seq = 494
current_ts = 201.231522
current_received_ts = 201.231323
current_seq = 504
count = 21
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.120316/494, current 201.231522/504: elapsed=111206.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.220398
last_received_ts = 201.220551
last_seq = 503
current_ts = 201.331604
current_received_ts = 201.331680
current_seq = 513
count = 21
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.220398/503, current 201.331604/513: elapsed=111204.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.231522
last_received_ts = 201.231323
last_seq = 504
current_ts = 201.342728
current_received_ts = 201.342545
current_seq = 514
count = 22
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.231522/504, current 201.342728/514: elapsed=111209.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.331604
last_received_ts = 201.331680
last_seq = 513
current_ts = 201.442795
current_received_ts = 201.443085
current_seq = 523
count = 22
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.331604/513, current 201.442795/523: elapsed=111199.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.342728
last_received_ts = 201.342545
last_seq = 514
current_ts = 201.453918
current_received_ts = 201.453903
current_seq = 524
count = 23
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.342728/514, current 201.453918/524: elapsed=111198.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.442795
last_received_ts = 201.443085
last_seq = 523
current_ts = 201.554001
current_received_ts = 201.554199
current_seq = 533
count = 23
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.442795/523, current 201.554001/533: elapsed=111199.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.453918
last_received_ts = 201.453903
last_seq = 524
current_ts = 201.565109
current_received_ts = 201.565094
current_seq = 534
count = 24
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.453918/524, current 201.565109/534: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.554001
last_received_ts = 201.554199
last_seq = 533
current_ts = 201.665192
current_received_ts = 201.665390
current_seq = 543
count = 24
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.554001/533, current 201.665192/543: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.565109
last_received_ts = 201.565094
last_seq = 534
current_ts = 201.676315
current_received_ts = 201.676254
current_seq = 544
count = 25
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.565109/534, current 201.676315/544: elapsed=111199.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.665192
last_received_ts = 201.665390
last_seq = 543
current_ts = 201.776398
current_received_ts = 201.776520
current_seq = 553
count = 25
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.665192/543, current 201.776398/553: elapsed=111200.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.676315
last_received_ts = 201.676254
last_seq = 544
current_ts = 201.787506
current_received_ts = 201.787384
current_seq = 554
count = 26
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.676315/544, current 201.787506/554: elapsed=111195.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.776398
last_received_ts = 201.776520
last_seq = 553
current_ts = 201.887589
current_received_ts = 201.887665
current_seq = 563
count = 26
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.776398/553, current 201.887589/563: elapsed=111196.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.787506
last_received_ts = 201.787384
last_seq = 554
current_ts = 201.898697
current_received_ts = 201.898529
current_seq = 564
count = 27
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.787506/554, current 201.898697/564: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.887589
last_received_ts = 201.887665
last_seq = 563
current_ts = 201.998795
current_received_ts = 201.998657
current_seq = 573
count = 27
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.887589/563, current 201.998795/573: elapsed=111198.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 201.898697
last_received_ts = 201.898529
last_seq = 564
current_ts = 202.009903
current_received_ts = 202.009811
current_seq = 574
count = 28
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 201.898697/564, current 202.009903/574: elapsed=111201.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 201.998795
last_received_ts = 201.998657
last_seq = 573
current_ts = 202.109985
current_received_ts = 202.110214
current_seq = 583
count = 28
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 201.998795/573, current 202.109985/583: elapsed=111196.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.009903
last_received_ts = 202.009811
last_seq = 574
current_ts = 202.121094
current_received_ts = 202.121216
current_seq = 584
count = 29
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.009903/574, current 202.121094/584: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.109985
last_received_ts = 202.110214
last_seq = 583
current_ts = 202.221176
current_received_ts = 202.221375
current_seq = 593
count = 29
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.109985/583, current 202.221176/593: elapsed=111195.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.121094
last_received_ts = 202.121216
last_seq = 584
current_ts = 202.232300
current_received_ts = 202.232285
current_seq = 594
count = 30
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.121094/584, current 202.232300/594: elapsed=111201.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.221176
last_received_ts = 202.221375
last_seq = 593
current_ts = 202.332382
current_received_ts = 202.332489
current_seq = 603
count = 30
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.221176/593, current 202.332382/603: elapsed=111197.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.232300
last_received_ts = 202.232285
last_seq = 594
current_ts = 202.343491
current_received_ts = 202.343781
current_seq = 604
count = 31
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.232300/594, current 202.343491/604: elapsed=111195.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.332382
last_received_ts = 202.332489
last_seq = 603
current_ts = 202.443558
current_received_ts = 202.443741
current_seq = 613
count = 31
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.332382/603, current 202.443558/613: elapsed=111190.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.343491
last_received_ts = 202.343781
last_seq = 604
current_ts = 202.454681
current_received_ts = 202.454529
current_seq = 614
count = 32
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.343491/604, current 202.454681/614: elapsed=111188.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.443558
last_received_ts = 202.443741
last_seq = 613
current_ts = 202.554749
current_received_ts = 202.554947
current_seq = 623
count = 32
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.443558/613, current 202.554749/623: elapsed=111189.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.454681
last_received_ts = 202.454529
last_seq = 614
current_ts = 202.565872
current_received_ts = 202.565796
current_seq = 624
count = 33
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.454681/614, current 202.565872/624: elapsed=111189.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.554749
last_received_ts = 202.554947
last_seq = 623
current_ts = 202.665939
current_received_ts = 202.666199
current_seq = 633
count = 33
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.554749/623, current 202.665939/633: elapsed=111190.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.565872
last_received_ts = 202.565796
last_seq = 624
current_ts = 202.677063
current_received_ts = 202.677185
current_seq = 634
count = 34
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.565872/624, current 202.677063/634: elapsed=111193.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.665939
last_received_ts = 202.666199
last_seq = 633
current_ts = 202.777130
current_received_ts = 202.777252
current_seq = 643
count = 34
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.665939/633, current 202.777130/643: elapsed=111189.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.677063
last_received_ts = 202.677185
last_seq = 634
current_ts = 202.788254
current_received_ts = 202.788422
current_seq = 644
count = 35
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.677063/634, current 202.788254/644: elapsed=111185.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.777130
last_received_ts = 202.777252
last_seq = 643
current_ts = 202.888321
current_received_ts = 202.888519
current_seq = 653
count = 35
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.777130/643, current 202.888321/653: elapsed=111188.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.788254
last_received_ts = 202.788422
last_seq = 644
current_ts = 202.899445
current_received_ts = 202.899246
current_seq = 654
count = 36
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.788254/644, current 202.899445/654: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.888321
last_received_ts = 202.888519
last_seq = 653
current_ts = 202.999512
current_received_ts = 202.999634
current_seq = 663
count = 36
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.888321/653, current 202.999512/663: elapsed=111192.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 202.899445
last_received_ts = 202.899246
last_seq = 654
current_ts = 203.010635
current_received_ts = 203.010727
current_seq = 664
count = 37
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 202.899445/654, current 203.010635/664: elapsed=111185.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 202.999512
last_received_ts = 202.999634
last_seq = 663
current_ts = 203.110703
current_received_ts = 203.110794
current_seq = 673
count = 37
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 202.999512/663, current 203.110703/673: elapsed=111185.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.010635
last_received_ts = 203.010727
last_seq = 664
current_ts = 203.121811
current_received_ts = 203.121658
current_seq = 674
count = 38
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.010635/664, current 203.121811/674: elapsed=111188.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.110703
last_received_ts = 203.110794
last_seq = 673
current_ts = 203.221893
current_received_ts = 203.221924
current_seq = 683
count = 38
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.110703/673, current 203.221893/683: elapsed=111189.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.121811
last_received_ts = 203.121658
last_seq = 674
current_ts = 203.233017
current_received_ts = 203.232834
current_seq = 684
count = 39
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.121811/674, current 203.233017/684: elapsed=111194.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.221893
last_received_ts = 203.221924
last_seq = 683
current_ts = 203.333084
current_received_ts = 203.333191
current_seq = 693
count = 39
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.221893/683, current 203.333084/693: elapsed=111193.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.233017
last_received_ts = 203.232834
last_seq = 684
current_ts = 203.344193
current_received_ts = 203.344131
current_seq = 694
count = 40
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.233017/684, current 203.344193/694: elapsed=111185.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.333084
last_received_ts = 203.333191
last_seq = 693
current_ts = 203.444260
current_received_ts = 203.444366
current_seq = 703
count = 40
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.333084/693, current 203.444260/703: elapsed=111180.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.344193
last_received_ts = 203.344131
last_seq = 694
current_ts = 203.455383
current_received_ts = 203.455215
current_seq = 704
count = 41
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.344193/694, current 203.455383/704: elapsed=111183.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.444260
last_received_ts = 203.444366
last_seq = 703
current_ts = 203.555435
current_received_ts = 203.555634
current_seq = 713
count = 41
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.444260/703, current 203.555435/713: elapsed=111182.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.455383
last_received_ts = 203.455215
last_seq = 704
current_ts = 203.566559
current_received_ts = 203.566406
current_seq = 714
count = 42
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.455383/704, current 203.566559/714: elapsed=111185.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.555435
last_received_ts = 203.555634
last_seq = 713
current_ts = 203.666626
current_received_ts = 203.666718
current_seq = 723
count = 42
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.555435/713, current 203.666626/723: elapsed=111184.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.566559
last_received_ts = 203.566406
last_seq = 714
current_ts = 203.677750
current_received_ts = 203.677567
current_seq = 724
count = 43
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.566559/714, current 203.677750/724: elapsed=111180.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.666626
last_received_ts = 203.666718
last_seq = 723
current_ts = 203.777802
current_received_ts = 203.777893
current_seq = 733
count = 43
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.666626/723, current 203.777802/733: elapsed=111182.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.677750
last_received_ts = 203.677567
last_seq = 724
current_ts = 203.788925
current_received_ts = 203.788864
current_seq = 734
count = 44
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.677750/724, current 203.788925/734: elapsed=111181.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.777802
last_received_ts = 203.777893
last_seq = 733
current_ts = 203.888992
current_received_ts = 203.889175
current_seq = 743
count = 44
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.777802/733, current 203.888992/743: elapsed=111179.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.788925
last_received_ts = 203.788864
last_seq = 734
current_ts = 203.900101
current_received_ts = 203.900299
current_seq = 744
count = 45
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.788925/734, current 203.900101/744: elapsed=111179.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 203.888992
last_received_ts = 203.889175
last_seq = 743
current_ts = 204.000168
current_received_ts = 204.000336
current_seq = 753
count = 45
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 203.888992/743, current 204.000168/753: elapsed=111181.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 203.900101
last_received_ts = 203.900299
last_seq = 744
current_ts = 204.011292
current_received_ts = 204.011139
current_seq = 754
count = 46
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 203.900101/744, current 204.011292/754: elapsed=111182.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.000168
last_received_ts = 204.000336
last_seq = 753
current_ts = 204.111359
current_received_ts = 204.111450
current_seq = 763
count = 46
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.000168/753, current 204.111359/763: elapsed=111186.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.011292
last_received_ts = 204.011139
last_seq = 754
current_ts = 204.122467
current_received_ts = 204.122559
current_seq = 764
count = 47
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.011292/754, current 204.122467/764: elapsed=111184.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.111359
last_received_ts = 204.111450
last_seq = 763
current_ts = 204.222534
current_received_ts = 204.222488
current_seq = 773
count = 47
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.111359/763, current 204.222534/773: elapsed=111177.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.122467
last_received_ts = 204.122559
last_seq = 764
current_ts = 204.233658
current_received_ts = 204.233505
current_seq = 774
count = 48
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.122467/764, current 204.233658/774: elapsed=111181.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.222534
last_received_ts = 204.222488
last_seq = 773
current_ts = 204.333710
current_received_ts = 204.333649
current_seq = 783
count = 48
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.222534/773, current 204.333710/783: elapsed=111184.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.233658
last_received_ts = 204.233505
last_seq = 774
current_ts = 204.344833
current_received_ts = 204.344772
current_seq = 784
count = 49
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.233658/774, current 204.344833/784: elapsed=111179.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.333710
last_received_ts = 204.333649
last_seq = 783
current_ts = 204.444885
current_received_ts = 204.445145
current_seq = 793
count = 49
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.333710/783, current 204.444885/793: elapsed=111177.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.344833
last_received_ts = 204.344772
last_seq = 784
current_ts = 204.456009
current_received_ts = 204.456161
current_seq = 794
count = 50
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.344833/784, current 204.456009/794: elapsed=111180.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.444885
last_received_ts = 204.445145
last_seq = 793
current_ts = 204.556061
current_received_ts = 204.556244
current_seq = 803
count = 50
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.444885/793, current 204.556061/803: elapsed=111176.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.456009
last_received_ts = 204.456161
last_seq = 794
current_ts = 204.567184
current_received_ts = 204.567108
current_seq = 804
count = 51
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.456009/794, current 204.567184/804: elapsed=111172.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.556061
last_received_ts = 204.556244
last_seq = 803
current_ts = 204.667236
current_received_ts = 204.667435
current_seq = 813
count = 51
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.556061/803, current 204.667236/813: elapsed=111171.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.567184
last_received_ts = 204.567108
last_seq = 804
current_ts = 204.678360
current_received_ts = 204.678238
current_seq = 814
count = 52
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.567184/804, current 204.678360/814: elapsed=111177.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.667236
last_received_ts = 204.667435
last_seq = 813
current_ts = 204.778412
current_received_ts = 204.778503
current_seq = 823
count = 52
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.667236/813, current 204.778412/823: elapsed=111175.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.678360
last_received_ts = 204.678238
last_seq = 814
current_ts = 204.789536
current_received_ts = 204.789474
current_seq = 824
count = 53
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.678360/814, current 204.789536/824: elapsed=111177.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.778412
last_received_ts = 204.778503
last_seq = 823
current_ts = 204.889587
current_received_ts = 204.889771
current_seq = 833
count = 53
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.778412/823, current 204.889587/833: elapsed=111175.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.789536
last_received_ts = 204.789474
last_seq = 824
current_ts = 204.900711
current_received_ts = 204.900543
current_seq = 834
count = 54
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.789536/824, current 204.900711/834: elapsed=111171.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 204.889587
last_received_ts = 204.889771
last_seq = 833
current_ts = 205.000763
current_received_ts = 205.000854
current_seq = 843
count = 54
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 204.889587/833, current 205.000763/843: elapsed=111175.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 204.900711
last_received_ts = 204.900543
last_seq = 834
current_ts = 205.011887
current_received_ts = 205.011795
current_seq = 844
count = 55
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 204.900711/834, current 205.011887/844: elapsed=111174.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.000763
last_received_ts = 205.000854
last_seq = 843
current_ts = 205.111938
current_received_ts = 205.112259
current_seq = 853
count = 55
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.000763/843, current 205.111938/853: elapsed=111175.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.011887
last_received_ts = 205.011795
last_seq = 844
current_ts = 205.123062
current_received_ts = 205.123062
current_seq = 854
count = 56
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.011887/844, current 205.123062/854: elapsed=111175.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.111938
last_received_ts = 205.112259
last_seq = 853
current_ts = 205.223114
current_received_ts = 205.223312
current_seq = 863
count = 56
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.111938/853, current 205.223114/863: elapsed=111178.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.123062
last_received_ts = 205.123062
last_seq = 854
current_ts = 205.234238
current_received_ts = 205.234238
current_seq = 864
count = 57
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.123062/854, current 205.234238/864: elapsed=111177.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.223114
last_received_ts = 205.223312
last_seq = 863
current_ts = 205.334290
current_received_ts = 205.334396
current_seq = 873
count = 57
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.223114/863, current 205.334290/873: elapsed=111172.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.234238
last_received_ts = 205.234238
last_seq = 864
current_ts = 205.345413
current_received_ts = 205.345383
current_seq = 874
count = 58
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.234238/864, current 205.345413/874: elapsed=111174.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.334290
last_received_ts = 205.334396
last_seq = 873
current_ts = 205.445465
current_received_ts = 205.445633
current_seq = 883
count = 58
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.334290/873, current 205.445465/883: elapsed=111174.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.345413
last_received_ts = 205.345383
last_seq = 874
current_ts = 205.456573
current_received_ts = 205.456406
current_seq = 884
count = 59
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.345413/874, current 205.456573/884: elapsed=111172.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.445465
last_received_ts = 205.445633
last_seq = 883
current_ts = 205.556625
current_received_ts = 205.556839
current_seq = 893
count = 59
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.445465/883, current 205.556625/893: elapsed=111164.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.456573
last_received_ts = 205.456406
last_seq = 884
current_ts = 205.567749
current_received_ts = 205.567566
current_seq = 894
count = 60
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.456573/884, current 205.567749/894: elapsed=111167.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.556625
last_received_ts = 205.556839
last_seq = 893
current_ts = 205.667801
current_received_ts = 205.667984
current_seq = 903
count = 60
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.556625/893, current 205.667801/903: elapsed=111171.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.567749
last_received_ts = 205.567566
last_seq = 894
current_ts = 205.678909
current_received_ts = 205.678741
current_seq = 904
count = 61
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.567749/894, current 205.678909/904: elapsed=111170.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.667801
last_received_ts = 205.667984
last_seq = 903
current_ts = 205.778961
current_received_ts = 205.779160
current_seq = 913
count = 61
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.667801/903, current 205.778961/913: elapsed=111168.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.678909
last_received_ts = 205.678741
last_seq = 904
current_ts = 205.790085
current_received_ts = 205.790054
current_seq = 914
count = 62
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.678909/904, current 205.790085/914: elapsed=111166.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.778961
last_received_ts = 205.779160
last_seq = 913
current_ts = 205.890137
current_received_ts = 205.890350
current_seq = 923
count = 62
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.778961/913, current 205.890137/923: elapsed=111169.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.790085
last_received_ts = 205.790054
last_seq = 914
current_ts = 205.901245
current_received_ts = 205.901199
current_seq = 924
count = 63
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.790085/914, current 205.901245/924: elapsed=111167.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 205.890137
last_received_ts = 205.890350
last_seq = 923
current_ts = 206.001297
current_received_ts = 206.001389
current_seq = 933
count = 63
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 205.890137/923, current 206.001297/933: elapsed=111169.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 205.901245
last_received_ts = 205.901199
last_seq = 924
current_ts = 206.012421
current_received_ts = 206.012207
current_seq = 934
count = 64
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 205.901245/924, current 206.012421/934: elapsed=111167.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 206.001297
last_received_ts = 206.001389
last_seq = 933
current_ts = 206.112473
current_received_ts = 206.112564
current_seq = 943
count = 64
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 206.001297/933, current 206.112473/943: elapsed=111166.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 206.012421
last_received_ts = 206.012207
last_seq = 934
current_ts = 206.123581
current_received_ts = 206.123459
current_seq = 944
count = 65
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 206.012421/934, current 206.123581/944: elapsed=111171.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 206.112473
last_received_ts = 206.112564
last_seq = 943
current_ts = 206.223633
current_received_ts = 206.223785
current_seq = 953
count = 65
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 206.112473/943, current 206.223633/953: elapsed=111168.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 206.123581
last_received_ts = 206.123459
last_seq = 944
current_ts = 206.234756
current_received_ts = 206.234680
current_seq = 954
count = 66
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 206.123581/944, current 206.234756/954: elapsed=111167.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 206.223633
last_received_ts = 206.223785
last_seq = 953
current_ts = 206.334808
current_received_ts = 206.334976
current_seq = 963
count = 66
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 206.223633/953, current 206.334808/963: elapsed=111166.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = flip
last_ts = 206.234756
last_received_ts = 206.234680
last_seq = 954
current_ts = 206.345917
current_received_ts = 206.345886
current_seq = 964
count = 67
seq_step = 1
(kms_flip:2540) DEBUG: flip ts/seq: last 206.234756/954, current 206.345917/964: elapsed=111168.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: name = vblank
last_ts = 206.334808
last_received_ts = 206.334976
last_seq = 963
current_ts = 206.445969
current_received_ts = 206.446243
current_seq = 973
count = 67
seq_step = 10
(kms_flip:2540) DEBUG: vblank ts/seq: last 206.334808/963, current 206.445969/973: elapsed=111165.0us expected=110936.2us +- 554.7us, error 0.2%
(kms_flip:2540) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2540) DEBUG: expected 681, counted 680, encoder type 2
(kms_flip:2540) DEBUG: dropped frames, expected 681, counted 680, encoder type 2
(kms_flip:2540) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2540) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2540) igt_core-INFO: Stack trace:
(kms_flip:2540) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2540) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2540) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2540) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2540) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2540) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2540) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2540) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-eDP1: FAIL (12.088s)
Subtest flip-vs-absolute-wf_vblank: FAIL (36.515s)
(kms_flip:2540) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2540) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2540) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2540) igt_kms-CRITICAL: DPMS property not found on 241