Results for igt@kms_flip@flip-vs-blocking-wf-vblank

shard-dg2-6

IGT-Version: 1.30-g613e57cba (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16239-gf02ab9f6e182+ x86_64)

Using IGT_SRANDOM=1741329337 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-blocking-wf-vblank
Starting dynamic subtest: A-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16668.7us +- 5.250us accuracy 0.09%
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-HDMI-A3: FAIL (10.291s)
Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16961.5us +- 8.140us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16962us +- 8.140us, difference 294.8us (36.2 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-HDMI-A3: FAIL (5.938s)
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16804.4us +- 7.848us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 16804us +- 7.848us, difference 137.7us (17.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 C-HDMI-A3: FAIL (11.205s)
Starting dynamic subtest: D-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16704.8us +- 4.435us accuracy 0.08%
vblank interval differs from modeline! expected 16666.7us, measured 16705us +- 4.435us, difference 38.1us (8.6 sigma)
Dynamic subtest D-HDMI-A3: SUCCESS (7.958s)
Subtest flip-vs-blocking-wf-vblank: FAIL (35.406s)

Starting subtest: flip-vs-blocking-wf-vblank
Starting dynamic subtest: A-HDMI-A3
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2495) DEBUG: No stale events found
(kms_flip:2495) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2495) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2495) INFO: Expected frametime: 16667us; measured 16668.7us +- 5.250us accuracy 0.09%
(kms_flip:2495) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 339.004913
current_received_ts = 339.154724
current_seq = 8513
count = 0
seq_step = 1
(kms_flip:2495) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 339.154938
current_received_ts = 339.154633
current_seq = 8522
count = 0
seq_step = 10
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.004913
last_received_ts = 339.154724
last_seq = 8513
current_ts = 339.171600
current_received_ts = 339.321381
current_seq = 8523
count = 1
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.004913/8513, current 339.171600/8523: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.154938
last_received_ts = 339.154633
last_seq = 8522
current_ts = 339.321625
current_received_ts = 339.321320
current_seq = 8532
count = 1
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.154938/8522, current 339.321625/8532: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.171600
last_received_ts = 339.321381
last_seq = 8523
current_ts = 339.338287
current_received_ts = 339.488129
current_seq = 8533
count = 2
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.171600/8523, current 339.338287/8533: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.321625
last_received_ts = 339.321320
last_seq = 8532
current_ts = 339.488312
current_received_ts = 339.488068
current_seq = 8542
count = 2
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.321625/8532, current 339.488312/8542: elapsed=166692.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.338287
last_received_ts = 339.488129
last_seq = 8533
current_ts = 339.504974
current_received_ts = 339.654755
current_seq = 8543
count = 3
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.338287/8533, current 339.504974/8543: elapsed=166695.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.488312
last_received_ts = 339.488068
last_seq = 8542
current_ts = 339.654999
current_received_ts = 339.654694
current_seq = 8552
count = 3
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.488312/8542, current 339.654999/8552: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.504974
last_received_ts = 339.654755
last_seq = 8543
current_ts = 339.671661
current_received_ts = 339.821472
current_seq = 8553
count = 4
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.504974/8543, current 339.671661/8553: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.654999
last_received_ts = 339.654694
last_seq = 8552
current_ts = 339.821686
current_received_ts = 339.821411
current_seq = 8562
count = 4
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.654999/8552, current 339.821686/8562: elapsed=166689.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.671661
last_received_ts = 339.821472
last_seq = 8553
current_ts = 339.838348
current_received_ts = 339.988129
current_seq = 8563
count = 5
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.671661/8553, current 339.838348/8563: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.821686
last_received_ts = 339.821411
last_seq = 8562
current_ts = 339.988373
current_received_ts = 339.988068
current_seq = 8572
count = 5
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.821686/8562, current 339.988373/8572: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 339.838348
last_received_ts = 339.988129
last_seq = 8563
current_ts = 340.005035
current_received_ts = 340.154816
current_seq = 8573
count = 6
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 339.838348/8563, current 340.005035/8573: elapsed=166690.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 339.988373
last_received_ts = 339.988068
last_seq = 8572
current_ts = 340.155060
current_received_ts = 340.154755
current_seq = 8582
count = 6
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 339.988373/8572, current 340.155060/8582: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.005035
last_received_ts = 340.154816
last_seq = 8573
current_ts = 340.171722
current_received_ts = 340.321472
current_seq = 8583
count = 7
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.005035/8573, current 340.171722/8583: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.155060
last_received_ts = 340.154755
last_seq = 8582
current_ts = 340.321747
current_received_ts = 340.321411
current_seq = 8592
count = 7
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.155060/8582, current 340.321747/8592: elapsed=166690.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.171722
last_received_ts = 340.321472
last_seq = 8583
current_ts = 340.338409
current_received_ts = 340.488220
current_seq = 8593
count = 8
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.171722/8583, current 340.338409/8593: elapsed=166689.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.321747
last_received_ts = 340.321411
last_seq = 8592
current_ts = 340.488434
current_received_ts = 340.488159
current_seq = 8602
count = 8
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.321747/8592, current 340.488434/8602: elapsed=166693.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.338409
last_received_ts = 340.488220
last_seq = 8593
current_ts = 340.505096
current_received_ts = 340.654877
current_seq = 8603
count = 9
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.338409/8593, current 340.505096/8603: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.488434
last_received_ts = 340.488159
last_seq = 8602
current_ts = 340.655121
current_received_ts = 340.654816
current_seq = 8612
count = 9
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.488434/8602, current 340.655121/8612: elapsed=166684.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.505096
last_received_ts = 340.654877
last_seq = 8603
current_ts = 340.671783
current_received_ts = 340.821411
current_seq = 8613
count = 10
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.505096/8603, current 340.671783/8613: elapsed=166689.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.655121
last_received_ts = 340.654816
last_seq = 8612
current_ts = 340.821808
current_received_ts = 340.821350
current_seq = 8622
count = 10
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.655121/8612, current 340.821808/8622: elapsed=166697.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.671783
last_received_ts = 340.821411
last_seq = 8613
current_ts = 340.838470
current_received_ts = 340.988190
current_seq = 8623
count = 11
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.671783/8613, current 340.838470/8623: elapsed=166690.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.821808
last_received_ts = 340.821350
last_seq = 8622
current_ts = 340.988525
current_received_ts = 340.988129
current_seq = 8632
count = 11
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.821808/8622, current 340.988525/8632: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 340.838470
last_received_ts = 340.988190
last_seq = 8623
current_ts = 341.005188
current_received_ts = 341.154785
current_seq = 8633
count = 12
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 340.838470/8623, current 341.005188/8633: elapsed=166696.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 340.988525
last_received_ts = 340.988129
last_seq = 8632
current_ts = 341.155212
current_received_ts = 341.154724
current_seq = 8642
count = 12
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 340.988525/8632, current 341.155212/8642: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.005188
last_received_ts = 341.154785
last_seq = 8633
current_ts = 341.171875
current_received_ts = 341.321686
current_seq = 8643
count = 13
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.005188/8633, current 341.171875/8643: elapsed=166686.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.155212
last_received_ts = 341.154724
last_seq = 8642
current_ts = 341.321899
current_received_ts = 341.321625
current_seq = 8652
count = 13
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.155212/8642, current 341.321899/8652: elapsed=166693.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.171875
last_received_ts = 341.321686
last_seq = 8643
current_ts = 341.338562
current_received_ts = 341.488342
current_seq = 8653
count = 14
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.171875/8643, current 341.338562/8653: elapsed=166688.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.321899
last_received_ts = 341.321625
last_seq = 8652
current_ts = 341.488586
current_received_ts = 341.488251
current_seq = 8662
count = 14
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.321899/8652, current 341.488586/8662: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.338562
last_received_ts = 341.488342
last_seq = 8653
current_ts = 341.505249
current_received_ts = 341.655090
current_seq = 8663
count = 15
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.338562/8653, current 341.505249/8663: elapsed=166688.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.488586
last_received_ts = 341.488251
last_seq = 8662
current_ts = 341.655273
current_received_ts = 341.654938
current_seq = 8672
count = 15
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.488586/8662, current 341.655273/8672: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.505249
last_received_ts = 341.655090
last_seq = 8663
current_ts = 341.671936
current_received_ts = 341.821747
current_seq = 8673
count = 16
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.505249/8663, current 341.671936/8673: elapsed=166698.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.655273
last_received_ts = 341.654938
last_seq = 8672
current_ts = 341.821960
current_received_ts = 341.821686
current_seq = 8682
count = 16
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.655273/8672, current 341.821960/8682: elapsed=166698.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.671936
last_received_ts = 341.821747
last_seq = 8673
current_ts = 341.838623
current_received_ts = 341.988281
current_seq = 8683
count = 17
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.671936/8673, current 341.838623/8683: elapsed=166691.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.821960
last_received_ts = 341.821686
last_seq = 8682
current_ts = 341.988647
current_received_ts = 341.988220
current_seq = 8692
count = 17
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.821960/8682, current 341.988647/8692: elapsed=166691.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 341.838623
last_received_ts = 341.988281
last_seq = 8683
current_ts = 342.005310
current_received_ts = 342.155151
current_seq = 8693
count = 18
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 341.838623/8683, current 342.005310/8693: elapsed=166683.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 341.988647
last_received_ts = 341.988220
last_seq = 8692
current_ts = 342.155334
current_received_ts = 342.155060
current_seq = 8702
count = 18
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 341.988647/8692, current 342.155334/8702: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.005310
last_received_ts = 342.155151
last_seq = 8693
current_ts = 342.172028
current_received_ts = 342.321808
current_seq = 8703
count = 19
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.005310/8693, current 342.172028/8703: elapsed=166702.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.155334
last_received_ts = 342.155060
last_seq = 8702
current_ts = 342.322052
current_received_ts = 342.321747
current_seq = 8712
count = 19
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.155334/8702, current 342.322052/8712: elapsed=166700.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.172028
last_received_ts = 342.321808
last_seq = 8703
current_ts = 342.338715
current_received_ts = 342.488525
current_seq = 8713
count = 20
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.172028/8703, current 342.338715/8713: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.322052
last_received_ts = 342.321747
last_seq = 8712
current_ts = 342.488739
current_received_ts = 342.488464
current_seq = 8722
count = 20
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.322052/8712, current 342.488739/8722: elapsed=166688.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.338715
last_received_ts = 342.488525
last_seq = 8713
current_ts = 342.505402
current_received_ts = 342.655212
current_seq = 8723
count = 21
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.338715/8713, current 342.505402/8723: elapsed=166696.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.488739
last_received_ts = 342.488464
last_seq = 8722
current_ts = 342.655426
current_received_ts = 342.655151
current_seq = 8732
count = 21
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.488739/8722, current 342.655426/8732: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.505402
last_received_ts = 342.655212
last_seq = 8723
current_ts = 342.672089
current_received_ts = 342.821808
current_seq = 8733
count = 22
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.505402/8723, current 342.672089/8733: elapsed=166691.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.655426
last_received_ts = 342.655151
last_seq = 8732
current_ts = 342.822113
current_received_ts = 342.821747
current_seq = 8742
count = 22
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.655426/8732, current 342.822113/8742: elapsed=166692.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.672089
last_received_ts = 342.821808
last_seq = 8733
current_ts = 342.838776
current_received_ts = 342.988373
current_seq = 8743
count = 23
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.672089/8733, current 342.838776/8743: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.822113
last_received_ts = 342.821747
last_seq = 8742
current_ts = 342.988800
current_received_ts = 342.988312
current_seq = 8752
count = 23
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.822113/8742, current 342.988800/8752: elapsed=166689.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 342.838776
last_received_ts = 342.988373
last_seq = 8743
current_ts = 343.005463
current_received_ts = 343.155243
current_seq = 8753
count = 24
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 342.838776/8743, current 343.005463/8753: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 342.988800
last_received_ts = 342.988312
last_seq = 8752
current_ts = 343.155487
current_received_ts = 343.155182
current_seq = 8762
count = 24
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 342.988800/8752, current 343.155487/8762: elapsed=166688.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.005463
last_received_ts = 343.155243
last_seq = 8753
current_ts = 343.172150
current_received_ts = 343.321777
current_seq = 8763
count = 25
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.005463/8753, current 343.172150/8763: elapsed=166684.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.155487
last_received_ts = 343.155182
last_seq = 8762
current_ts = 343.322174
current_received_ts = 343.321716
current_seq = 8772
count = 25
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.155487/8762, current 343.322174/8772: elapsed=166697.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.172150
last_received_ts = 343.321777
last_seq = 8763
current_ts = 343.338867
current_received_ts = 343.488617
current_seq = 8773
count = 26
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.172150/8763, current 343.338867/8773: elapsed=166700.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.322174
last_received_ts = 343.321716
last_seq = 8772
current_ts = 343.488861
current_received_ts = 343.488556
current_seq = 8782
count = 26
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.322174/8772, current 343.488861/8782: elapsed=166684.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.338867
last_received_ts = 343.488617
last_seq = 8773
current_ts = 343.505554
current_received_ts = 343.655304
current_seq = 8783
count = 27
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.338867/8773, current 343.505554/8783: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.488861
last_received_ts = 343.488556
last_seq = 8782
current_ts = 343.655548
current_received_ts = 343.655243
current_seq = 8792
count = 27
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.488861/8782, current 343.655548/8792: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.505554
last_received_ts = 343.655304
last_seq = 8783
current_ts = 343.672241
current_received_ts = 343.822083
current_seq = 8793
count = 28
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.505554/8783, current 343.672241/8793: elapsed=166696.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.655548
last_received_ts = 343.655243
last_seq = 8792
current_ts = 343.822266
current_received_ts = 343.821960
current_seq = 8802
count = 28
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.655548/8792, current 343.822266/8802: elapsed=166689.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.672241
last_received_ts = 343.822083
last_seq = 8793
current_ts = 343.838928
current_received_ts = 343.988586
current_seq = 8803
count = 29
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.672241/8793, current 343.838928/8803: elapsed=166686.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.822266
last_received_ts = 343.821960
last_seq = 8802
current_ts = 343.988953
current_received_ts = 343.988525
current_seq = 8812
count = 29
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.822266/8802, current 343.988953/8812: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 343.838928
last_received_ts = 343.988586
last_seq = 8803
current_ts = 344.005615
current_received_ts = 344.155426
current_seq = 8813
count = 30
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 343.838928/8803, current 344.005615/8813: elapsed=166702.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 343.988953
last_received_ts = 343.988525
last_seq = 8812
current_ts = 344.155640
current_received_ts = 344.155365
current_seq = 8822
count = 30
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 343.988953/8812, current 344.155640/8822: elapsed=166704.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.005615
last_received_ts = 344.155426
last_seq = 8813
current_ts = 344.172302
current_received_ts = 344.321777
current_seq = 8823
count = 31
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.005615/8813, current 344.172302/8823: elapsed=166691.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.155640
last_received_ts = 344.155365
last_seq = 8822
current_ts = 344.322357
current_received_ts = 344.321747
current_seq = 8832
count = 31
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.155640/8822, current 344.322357/8832: elapsed=166694.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.172302
last_received_ts = 344.321777
last_seq = 8823
current_ts = 344.338989
current_received_ts = 344.488770
current_seq = 8833
count = 32
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.172302/8823, current 344.338989/8833: elapsed=166686.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.322357
last_received_ts = 344.321747
last_seq = 8832
current_ts = 344.489044
current_received_ts = 344.488708
current_seq = 8842
count = 32
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.322357/8832, current 344.489044/8842: elapsed=166686.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.338989
last_received_ts = 344.488770
last_seq = 8833
current_ts = 344.505707
current_received_ts = 344.655334
current_seq = 8843
count = 33
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.338989/8833, current 344.505707/8843: elapsed=166703.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.489044
last_received_ts = 344.488708
last_seq = 8842
current_ts = 344.655731
current_received_ts = 344.655273
current_seq = 8852
count = 33
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.489044/8842, current 344.655731/8852: elapsed=166698.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.505707
last_received_ts = 344.655334
last_seq = 8843
current_ts = 344.672394
current_received_ts = 344.822144
current_seq = 8853
count = 34
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.505707/8843, current 344.672394/8853: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.655731
last_received_ts = 344.655273
last_seq = 8852
current_ts = 344.822418
current_received_ts = 344.822083
current_seq = 8862
count = 34
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.655731/8852, current 344.822418/8862: elapsed=166684.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.672394
last_received_ts = 344.822144
last_seq = 8853
current_ts = 344.839081
current_received_ts = 344.988708
current_seq = 8863
count = 35
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.672394/8853, current 344.839081/8863: elapsed=166701.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.822418
last_received_ts = 344.822083
last_seq = 8862
current_ts = 344.989105
current_received_ts = 344.988647
current_seq = 8872
count = 35
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.822418/8862, current 344.989105/8872: elapsed=166696.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 344.839081
last_received_ts = 344.988708
last_seq = 8863
current_ts = 345.005768
current_received_ts = 345.155609
current_seq = 8873
count = 36
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 344.839081/8863, current 345.005768/8873: elapsed=166687.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 344.989105
last_received_ts = 344.988647
last_seq = 8872
current_ts = 345.155823
current_received_ts = 345.155548
current_seq = 8882
count = 36
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 344.989105/8872, current 345.155823/8882: elapsed=166700.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 345.005768
last_received_ts = 345.155609
last_seq = 8873
current_ts = 345.172455
current_received_ts = 345.322113
current_seq = 8883
count = 37
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 345.005768/8873, current 345.172455/8883: elapsed=166691.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 345.155823
last_received_ts = 345.155548
last_seq = 8882
current_ts = 345.322479
current_received_ts = 345.322052
current_seq = 8892
count = 37
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 345.155823/8882, current 345.322479/8892: elapsed=166685.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 345.172455
last_received_ts = 345.322113
last_seq = 8883
current_ts = 345.339172
current_received_ts = 345.488983
current_seq = 8893
count = 38
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 345.172455/8883, current 345.339172/8893: elapsed=166697.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 345.322479
last_received_ts = 345.322052
last_seq = 8892
current_ts = 345.489227
current_received_ts = 345.488922
current_seq = 8902
count = 38
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 345.322479/8892, current 345.489227/8902: elapsed=166729.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 345.339172
last_received_ts = 345.488983
last_seq = 8893
current_ts = 345.505890
current_received_ts = 345.655731
current_seq = 8903
count = 39
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 345.339172/8893, current 345.505890/8903: elapsed=166720.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 345.489227
last_received_ts = 345.488922
last_seq = 8902
current_ts = 345.655945
current_received_ts = 345.655640
current_seq = 8912
count = 39
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 345.489227/8902, current 345.655945/8912: elapsed=166723.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 345.505890
last_received_ts = 345.655731
last_seq = 8903
current_ts = 345.672607
current_received_ts = 345.824646
current_seq = 8913
count = 40
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 345.505890/8903, current 345.672607/8913: elapsed=166731.0us expected=166686.9us +- 833.4us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 345.655945
last_received_ts = 345.655640
last_seq = 8912
current_ts = 345.824890
current_received_ts = 345.824585
current_seq = 8922
count = 40
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 345.655945/8912, current 345.824890/8922: elapsed=168934.0us expected=166686.9us +- 833.4us, error 1.3%
(kms_flip:2495) DEBUG: inconsistent vblank ts/seq: last 345.655945/8912, current 345.824890/8922: elapsed=168934.0us expected=166686.9us
(kms_flip:2495) DEBUG: expected 161842, counted 400, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 161842, counted 400, encoder type 2
(kms_flip:2495) DEBUG: expected 161842, counted 400, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 161842, counted 400, encoder type 2
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2495) igt_core-INFO: Stack trace:
(kms_flip:2495) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2495) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2495) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2495) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2495) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2495) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2495) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2495) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A3: FAIL (10.291s)
Starting dynamic subtest: B-HDMI-A3
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=11, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2495) DEBUG: No stale events found
(kms_flip:2495) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2495) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2495) INFO: Expected frametime: 16667us; measured 16961.5us +- 8.140us accuracy 0.14%
(kms_flip:2495) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16962us +- 8.140us, difference 294.8us (36.2 sigma)
(kms_flip:2495) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 349.332703
current_received_ts = 349.485168
current_seq = 98
count = 0
seq_step = 1
(kms_flip:2495) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 349.485382
current_received_ts = 349.485107
current_seq = 107
count = 0
seq_step = 10
(kms_flip:2495) DEBUG: name = flip
last_ts = 349.332703
last_received_ts = 349.485168
last_seq = 98
current_ts = 349.502319
current_received_ts = 349.654785
current_seq = 108
count = 1
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 349.332703/98, current 349.502319/108: elapsed=169620.0us expected=169615.0us +- 848.1us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 349.485382
last_received_ts = 349.485107
last_seq = 107
current_ts = 349.654999
current_received_ts = 349.654724
current_seq = 117
count = 1
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 349.485382/107, current 349.654999/117: elapsed=169609.0us expected=169615.0us +- 848.1us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 349.502319
last_received_ts = 349.654785
last_seq = 108
current_ts = 349.671936
current_received_ts = 349.824066
current_seq = 118
count = 2
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 349.502319/108, current 349.671936/118: elapsed=169612.0us expected=169615.0us +- 848.1us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 349.654999
last_received_ts = 349.654724
last_seq = 117
current_ts = 349.824402
current_received_ts = 349.823944
current_seq = 127
count = 2
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 349.654999/117, current 349.824402/127: elapsed=169427.0us expected=169615.0us +- 848.1us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 349.671936
last_received_ts = 349.824066
last_seq = 118
current_ts = 349.841339
current_received_ts = 349.993469
current_seq = 128
count = 3
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 349.671936/118, current 349.841339/128: elapsed=169395.0us expected=169615.0us +- 848.1us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 349.824402
last_received_ts = 349.823944
last_seq = 127
current_ts = 349.993683
current_received_ts = 349.993408
current_seq = 137
count = 3
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 349.824402/127, current 349.993683/137: elapsed=169263.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 349.841339
last_received_ts = 349.993469
last_seq = 128
current_ts = 350.010590
current_received_ts = 350.162720
current_seq = 138
count = 4
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 349.841339/128, current 350.010590/138: elapsed=169254.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 349.993683
last_received_ts = 349.993408
last_seq = 137
current_ts = 350.162933
current_received_ts = 350.162659
current_seq = 147
count = 4
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 349.993683/137, current 350.162933/147: elapsed=169248.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.010590
last_received_ts = 350.162720
last_seq = 138
current_ts = 350.179840
current_received_ts = 350.332001
current_seq = 148
count = 5
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.010590/138, current 350.179840/148: elapsed=169254.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 350.162933
last_received_ts = 350.162659
last_seq = 147
current_ts = 350.332184
current_received_ts = 350.331909
current_seq = 157
count = 5
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 350.162933/147, current 350.332184/157: elapsed=169264.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.179840
last_received_ts = 350.332001
last_seq = 148
current_ts = 350.349121
current_received_ts = 350.501251
current_seq = 158
count = 6
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.179840/148, current 350.349121/158: elapsed=169259.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 350.332184
last_received_ts = 350.331909
last_seq = 157
current_ts = 350.501434
current_received_ts = 350.501190
current_seq = 167
count = 6
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 350.332184/157, current 350.501434/167: elapsed=169256.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.349121
last_received_ts = 350.501251
last_seq = 158
current_ts = 350.518372
current_received_ts = 350.670471
current_seq = 168
count = 7
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.349121/158, current 350.518372/168: elapsed=169263.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 350.501434
last_received_ts = 350.501190
last_seq = 167
current_ts = 350.670685
current_received_ts = 350.670410
current_seq = 177
count = 7
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 350.501434/167, current 350.670685/177: elapsed=169256.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.518372
last_received_ts = 350.670471
last_seq = 168
current_ts = 350.687622
current_received_ts = 350.839539
current_seq = 178
count = 8
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.518372/168, current 350.687622/178: elapsed=169248.0us expected=169615.0us +- 848.1us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 350.670685
last_received_ts = 350.670410
last_seq = 177
current_ts = 350.839752
current_received_ts = 350.839478
current_seq = 187
count = 8
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 350.670685/177, current 350.839752/187: elapsed=169060.0us expected=169615.0us +- 848.1us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.687622
last_received_ts = 350.839539
last_seq = 178
current_ts = 350.856659
current_received_ts = 351.008423
current_seq = 188
count = 9
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.687622/178, current 350.856659/188: elapsed=169038.0us expected=169615.0us +- 848.1us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 350.839752
last_received_ts = 350.839478
last_seq = 187
current_ts = 351.008698
current_received_ts = 351.008362
current_seq = 197
count = 9
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 350.839752/187, current 351.008698/197: elapsed=168948.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 350.856659
last_received_ts = 351.008423
last_seq = 188
current_ts = 351.025604
current_received_ts = 351.177429
current_seq = 198
count = 10
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 350.856659/188, current 351.025604/198: elapsed=168936.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 351.008698
last_received_ts = 351.008362
last_seq = 197
current_ts = 351.177643
current_received_ts = 351.177368
current_seq = 207
count = 10
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 351.008698/197, current 351.177643/207: elapsed=168946.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 351.025604
last_received_ts = 351.177429
last_seq = 198
current_ts = 351.194550
current_received_ts = 351.346405
current_seq = 208
count = 11
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 351.025604/198, current 351.194550/208: elapsed=168945.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 351.177643
last_received_ts = 351.177368
last_seq = 207
current_ts = 351.346588
current_received_ts = 351.346344
current_seq = 217
count = 11
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 351.177643/207, current 351.346588/217: elapsed=168941.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 351.194550
last_received_ts = 351.346405
last_seq = 208
current_ts = 351.363495
current_received_ts = 351.515320
current_seq = 218
count = 12
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 351.194550/208, current 351.363495/218: elapsed=168955.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 351.346588
last_received_ts = 351.346344
last_seq = 217
current_ts = 351.515533
current_received_ts = 351.515259
current_seq = 227
count = 12
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 351.346588/217, current 351.515533/227: elapsed=168938.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 351.363495
last_received_ts = 351.515320
last_seq = 218
current_ts = 351.532440
current_received_ts = 351.684265
current_seq = 228
count = 13
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 351.363495/218, current 351.532440/228: elapsed=168942.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 351.515533
last_received_ts = 351.515259
last_seq = 227
current_ts = 351.684479
current_received_ts = 351.684204
current_seq = 237
count = 13
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 351.515533/227, current 351.684479/237: elapsed=168948.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 351.532440
last_received_ts = 351.684265
last_seq = 228
current_ts = 351.701385
current_received_ts = 351.853088
current_seq = 238
count = 14
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 351.532440/228, current 351.701385/238: elapsed=168940.0us expected=169615.0us +- 848.1us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 351.684479
last_received_ts = 351.684204
last_seq = 237
current_ts = 351.853241
current_received_ts = 351.852966
current_seq = 247
count = 14
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 351.684479/237, current 351.853241/247: elapsed=168750.0us expected=169615.0us +- 848.1us, error 0.5%
(kms_flip:2495) DEBUG: inconsistent vblank ts/seq: last 351.684479/237, current 351.853241/247: elapsed=168750.0us expected=169615.0us
(kms_flip:2495) DEBUG: expected 159048, counted 140, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 159048, counted 140, encoder type 2
(kms_flip:2495) DEBUG: expected 159048, counted 140, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 159048, counted 140, encoder type 2
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2495) igt_core-INFO: Stack trace:
(kms_flip:2495) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2495) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2495) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2495) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2495) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2495) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2495) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2495) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (5.938s)
Starting dynamic subtest: C-HDMI-A3
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=12, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2495) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=17, pitch=7680)
(kms_flip:2495) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2495) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2495) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2495) DEBUG: No stale events found
(kms_flip:2495) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2495) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2495) INFO: Expected frametime: 16667us; measured 16804.4us +- 7.848us accuracy 0.14%
(kms_flip:2495) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16804us +- 7.848us, difference 137.7us (17.5 sigma)
(kms_flip:2495) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 355.331543
current_received_ts = 355.482544
current_seq = 110
count = 0
seq_step = 1
(kms_flip:2495) DEBUG: name = vblank
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 355.482788
current_received_ts = 355.482483
current_seq = 119
count = 0
seq_step = 10
(kms_flip:2495) DEBUG: name = flip
last_ts = 355.331543
last_received_ts = 355.482544
last_seq = 110
current_ts = 355.499573
current_received_ts = 355.650604
current_seq = 120
count = 1
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 355.331543/110, current 355.499573/120: elapsed=168040.0us expected=168043.8us +- 840.2us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 355.482788
last_received_ts = 355.482483
last_seq = 119
current_ts = 355.650818
current_received_ts = 355.650543
current_seq = 129
count = 1
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 355.482788/119, current 355.650818/129: elapsed=168036.0us expected=168043.8us +- 840.2us, error 0.0%
(kms_flip:2495) DEBUG: name = flip
last_ts = 355.499573
last_received_ts = 355.650604
last_seq = 120
current_ts = 355.667603
current_received_ts = 355.818573
current_seq = 130
count = 2
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 355.499573/120, current 355.667603/130: elapsed=168026.0us expected=168043.8us +- 840.2us, error 0.0%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 355.650818
last_received_ts = 355.650543
last_seq = 129
current_ts = 355.818756
current_received_ts = 355.818512
current_seq = 139
count = 2
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 355.650818/129, current 355.818756/139: elapsed=167954.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 355.667603
last_received_ts = 355.818573
last_seq = 130
current_ts = 355.835541
current_received_ts = 355.986450
current_seq = 140
count = 3
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 355.667603/130, current 355.835541/140: elapsed=167947.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 355.818756
last_received_ts = 355.818512
last_seq = 139
current_ts = 355.986633
current_received_ts = 355.986389
current_seq = 149
count = 3
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 355.818756/139, current 355.986633/149: elapsed=167880.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 355.835541
last_received_ts = 355.986450
last_seq = 140
current_ts = 356.003418
current_received_ts = 356.154327
current_seq = 150
count = 4
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 355.835541/140, current 356.003418/150: elapsed=167878.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 355.986633
last_received_ts = 355.986389
last_seq = 149
current_ts = 356.154510
current_received_ts = 356.154236
current_seq = 159
count = 4
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 355.986633/149, current 356.154510/159: elapsed=167876.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.003418
last_received_ts = 356.154327
last_seq = 150
current_ts = 356.171295
current_received_ts = 356.322174
current_seq = 160
count = 5
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.003418/150, current 356.171295/160: elapsed=167874.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.154510
last_received_ts = 356.154236
last_seq = 159
current_ts = 356.322388
current_received_ts = 356.322113
current_seq = 169
count = 5
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.154510/159, current 356.322388/169: elapsed=167875.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.171295
last_received_ts = 356.322174
last_seq = 160
current_ts = 356.339172
current_received_ts = 356.490112
current_seq = 170
count = 6
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.171295/160, current 356.339172/170: elapsed=167878.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.322388
last_received_ts = 356.322113
last_seq = 169
current_ts = 356.490265
current_received_ts = 356.490051
current_seq = 179
count = 6
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.322388/169, current 356.490265/179: elapsed=167879.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.339172
last_received_ts = 356.490112
last_seq = 170
current_ts = 356.507050
current_received_ts = 356.657959
current_seq = 180
count = 7
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.339172/170, current 356.507050/180: elapsed=167870.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.490265
last_received_ts = 356.490051
last_seq = 179
current_ts = 356.658142
current_received_ts = 356.657898
current_seq = 189
count = 7
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.490265/179, current 356.658142/189: elapsed=167867.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.507050
last_received_ts = 356.657959
last_seq = 180
current_ts = 356.674927
current_received_ts = 356.825653
current_seq = 190
count = 8
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.507050/180, current 356.674927/190: elapsed=167879.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.658142
last_received_ts = 356.657898
last_seq = 189
current_ts = 356.825958
current_received_ts = 356.825623
current_seq = 199
count = 8
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.658142/189, current 356.825958/199: elapsed=167809.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.674927
last_received_ts = 356.825653
last_seq = 190
current_ts = 356.842712
current_received_ts = 356.993500
current_seq = 200
count = 9
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.674927/190, current 356.842712/200: elapsed=167794.0us expected=168043.8us +- 840.2us, error 0.1%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.825958
last_received_ts = 356.825623
last_seq = 199
current_ts = 356.993683
current_received_ts = 356.993408
current_seq = 209
count = 9
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.825958/199, current 356.993683/209: elapsed=167740.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 356.842712
last_received_ts = 356.993500
last_seq = 200
current_ts = 357.010468
current_received_ts = 357.161163
current_seq = 210
count = 10
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 356.842712/200, current 357.010468/210: elapsed=167743.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 356.993683
last_received_ts = 356.993408
last_seq = 209
current_ts = 357.161407
current_received_ts = 357.161102
current_seq = 219
count = 10
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 356.993683/209, current 357.161407/219: elapsed=167731.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.010468
last_received_ts = 357.161163
last_seq = 210
current_ts = 357.178192
current_received_ts = 357.328979
current_seq = 220
count = 11
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.010468/210, current 357.178192/220: elapsed=167732.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.161407
last_received_ts = 357.161102
last_seq = 219
current_ts = 357.329163
current_received_ts = 357.328918
current_seq = 229
count = 11
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.161407/219, current 357.329163/229: elapsed=167746.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.178192
last_received_ts = 357.328979
last_seq = 220
current_ts = 357.345947
current_received_ts = 357.496704
current_seq = 230
count = 12
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.178192/220, current 357.345947/230: elapsed=167733.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.329163
last_received_ts = 357.328918
last_seq = 229
current_ts = 357.496887
current_received_ts = 357.496643
current_seq = 239
count = 12
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.329163/229, current 357.496887/239: elapsed=167734.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.345947
last_received_ts = 357.496704
last_seq = 230
current_ts = 357.513672
current_received_ts = 357.664429
current_seq = 240
count = 13
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.345947/230, current 357.513672/240: elapsed=167731.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.496887
last_received_ts = 357.496643
last_seq = 239
current_ts = 357.664642
current_received_ts = 357.664368
current_seq = 249
count = 13
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.496887/239, current 357.664642/249: elapsed=167737.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.513672
last_received_ts = 357.664429
last_seq = 240
current_ts = 357.681427
current_received_ts = 357.832153
current_seq = 250
count = 14
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.513672/240, current 357.681427/250: elapsed=167750.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.664642
last_received_ts = 357.664368
last_seq = 249
current_ts = 357.832306
current_received_ts = 357.832092
current_seq = 259
count = 14
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.664642/249, current 357.832306/259: elapsed=167676.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.681427
last_received_ts = 357.832153
last_seq = 250
current_ts = 357.849060
current_received_ts = 357.999725
current_seq = 260
count = 15
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.681427/250, current 357.849060/260: elapsed=167655.0us expected=168043.8us +- 840.2us, error 0.2%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.832306
last_received_ts = 357.832092
last_seq = 259
current_ts = 357.999939
current_received_ts = 357.999664
current_seq = 269
count = 15
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.832306/259, current 357.999939/269: elapsed=167612.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 357.849060
last_received_ts = 357.999725
last_seq = 260
current_ts = 358.016693
current_received_ts = 358.167328
current_seq = 270
count = 16
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 357.849060/260, current 358.016693/270: elapsed=167619.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 357.999939
last_received_ts = 357.999664
last_seq = 269
current_ts = 358.167542
current_received_ts = 358.167267
current_seq = 279
count = 16
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 357.999939/269, current 358.167542/279: elapsed=167611.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.016693
last_received_ts = 358.167328
last_seq = 270
current_ts = 358.184296
current_received_ts = 358.334961
current_seq = 280
count = 17
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.016693/270, current 358.184296/280: elapsed=167610.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 358.167542
last_received_ts = 358.167267
last_seq = 279
current_ts = 358.335144
current_received_ts = 358.334900
current_seq = 289
count = 17
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 358.167542/279, current 358.335144/289: elapsed=167620.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.184296
last_received_ts = 358.334961
last_seq = 280
current_ts = 358.351929
current_received_ts = 358.502563
current_seq = 290
count = 18
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.184296/280, current 358.351929/290: elapsed=167616.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 358.335144
last_received_ts = 358.334900
last_seq = 289
current_ts = 358.502777
current_received_ts = 358.502502
current_seq = 299
count = 18
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 358.335144/289, current 358.502777/299: elapsed=167611.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.351929
last_received_ts = 358.502563
last_seq = 290
current_ts = 358.519531
current_received_ts = 358.670166
current_seq = 300
count = 19
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.351929/290, current 358.519531/300: elapsed=167607.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 358.502777
last_received_ts = 358.502502
last_seq = 299
current_ts = 358.670380
current_received_ts = 358.670105
current_seq = 309
count = 19
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 358.502777/299, current 358.670380/309: elapsed=167607.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.519531
last_received_ts = 358.670166
last_seq = 300
current_ts = 358.687134
current_received_ts = 358.837738
current_seq = 310
count = 20
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.519531/300, current 358.687134/310: elapsed=167621.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 358.670380
last_received_ts = 358.670105
last_seq = 309
current_ts = 358.837921
current_received_ts = 358.837677
current_seq = 319
count = 20
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 358.670380/309, current 358.837921/319: elapsed=167558.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.687134
last_received_ts = 358.837738
last_seq = 310
current_ts = 358.854675
current_received_ts = 359.005188
current_seq = 320
count = 21
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.687134/310, current 358.854675/320: elapsed=167541.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 358.837921
last_received_ts = 358.837677
last_seq = 319
current_ts = 359.005432
current_received_ts = 359.005127
current_seq = 329
count = 21
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 358.837921/319, current 359.005432/329: elapsed=167506.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 358.854675
last_received_ts = 359.005188
last_seq = 320
current_ts = 359.022186
current_received_ts = 359.172638
current_seq = 330
count = 22
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 358.854675/320, current 359.022186/330: elapsed=167503.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.005432
last_received_ts = 359.005127
last_seq = 329
current_ts = 359.172943
current_received_ts = 359.172577
current_seq = 339
count = 22
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.005432/329, current 359.172943/339: elapsed=167496.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.022186
last_received_ts = 359.172638
last_seq = 330
current_ts = 359.189697
current_received_ts = 359.340240
current_seq = 340
count = 23
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.022186/330, current 359.189697/340: elapsed=167507.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.172943
last_received_ts = 359.172577
last_seq = 339
current_ts = 359.340454
current_received_ts = 359.340179
current_seq = 349
count = 23
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.172943/339, current 359.340454/349: elapsed=167514.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.189697
last_received_ts = 359.340240
last_seq = 340
current_ts = 359.357178
current_received_ts = 359.507751
current_seq = 350
count = 24
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.189697/340, current 359.357178/350: elapsed=167496.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.340454
last_received_ts = 359.340179
last_seq = 349
current_ts = 359.507965
current_received_ts = 359.507660
current_seq = 359
count = 24
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.340454/349, current 359.507965/359: elapsed=167508.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.357178
last_received_ts = 359.507751
last_seq = 350
current_ts = 359.524719
current_received_ts = 359.675262
current_seq = 360
count = 25
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.357178/350, current 359.524719/360: elapsed=167520.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.507965
last_received_ts = 359.507660
last_seq = 359
current_ts = 359.675476
current_received_ts = 359.675201
current_seq = 369
count = 25
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.507965/359, current 359.675476/369: elapsed=167507.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.524719
last_received_ts = 359.675262
last_seq = 360
current_ts = 359.692200
current_received_ts = 359.842712
current_seq = 370
count = 26
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.524719/360, current 359.692200/370: elapsed=167497.0us expected=168043.8us +- 840.2us, error 0.3%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.675476
last_received_ts = 359.675201
last_seq = 369
current_ts = 359.842896
current_received_ts = 359.842651
current_seq = 379
count = 26
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.675476/369, current 359.842896/379: elapsed=167445.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.692200
last_received_ts = 359.842712
last_seq = 370
current_ts = 359.859650
current_received_ts = 360.010162
current_seq = 380
count = 27
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.692200/370, current 359.859650/380: elapsed=167444.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 359.842896
last_received_ts = 359.842651
last_seq = 379
current_ts = 360.010315
current_received_ts = 360.010101
current_seq = 389
count = 27
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 359.842896/379, current 360.010315/389: elapsed=167414.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 359.859650
last_received_ts = 360.010162
last_seq = 380
current_ts = 360.027069
current_received_ts = 360.177521
current_seq = 390
count = 28
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 359.859650/380, current 360.027069/390: elapsed=167408.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.010315
last_received_ts = 360.010101
last_seq = 389
current_ts = 360.177734
current_received_ts = 360.177460
current_seq = 399
count = 28
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.010315/389, current 360.177734/399: elapsed=167411.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.027069
last_received_ts = 360.177521
last_seq = 390
current_ts = 360.194489
current_received_ts = 360.344879
current_seq = 400
count = 29
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.027069/390, current 360.194489/400: elapsed=167419.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.177734
last_received_ts = 360.177460
last_seq = 399
current_ts = 360.345123
current_received_ts = 360.344788
current_seq = 409
count = 29
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.177734/399, current 360.345123/409: elapsed=167401.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.194489
last_received_ts = 360.344879
last_seq = 400
current_ts = 360.361877
current_received_ts = 360.512360
current_seq = 410
count = 30
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.194489/400, current 360.361877/410: elapsed=167399.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.345123
last_received_ts = 360.344788
last_seq = 409
current_ts = 360.512573
current_received_ts = 360.512299
current_seq = 419
count = 30
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.345123/409, current 360.512573/419: elapsed=167424.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.361877
last_received_ts = 360.512360
last_seq = 410
current_ts = 360.529297
current_received_ts = 360.679779
current_seq = 420
count = 31
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.361877/410, current 360.529297/420: elapsed=167415.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.512573
last_received_ts = 360.512299
last_seq = 419
current_ts = 360.679962
current_received_ts = 360.679718
current_seq = 429
count = 31
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.512573/419, current 360.679962/429: elapsed=167414.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.529297
last_received_ts = 360.679779
last_seq = 420
current_ts = 360.696716
current_received_ts = 360.847137
current_seq = 430
count = 32
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.529297/420, current 360.696716/430: elapsed=167423.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.679962
last_received_ts = 360.679718
last_seq = 429
current_ts = 360.847321
current_received_ts = 360.847076
current_seq = 439
count = 32
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.679962/429, current 360.847321/439: elapsed=167359.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.696716
last_received_ts = 360.847137
last_seq = 430
current_ts = 360.864075
current_received_ts = 361.014465
current_seq = 440
count = 33
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.696716/430, current 360.864075/440: elapsed=167348.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 360.847321
last_received_ts = 360.847076
last_seq = 439
current_ts = 361.014648
current_received_ts = 361.014404
current_seq = 449
count = 33
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 360.847321/439, current 361.014648/449: elapsed=167327.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 360.864075
last_received_ts = 361.014465
last_seq = 440
current_ts = 361.031403
current_received_ts = 361.181793
current_seq = 450
count = 34
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 360.864075/440, current 361.031403/450: elapsed=167331.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.014648
last_received_ts = 361.014404
last_seq = 449
current_ts = 361.181976
current_received_ts = 361.181732
current_seq = 459
count = 34
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.014648/449, current 361.181976/459: elapsed=167331.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.031403
last_received_ts = 361.181793
last_seq = 450
current_ts = 361.198730
current_received_ts = 361.349152
current_seq = 460
count = 35
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.031403/450, current 361.198730/460: elapsed=167324.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.181976
last_received_ts = 361.181732
last_seq = 459
current_ts = 361.349304
current_received_ts = 361.349091
current_seq = 469
count = 35
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.181976/459, current 361.349304/469: elapsed=167329.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.198730
last_received_ts = 361.349152
last_seq = 460
current_ts = 361.366058
current_received_ts = 361.516449
current_seq = 470
count = 36
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.198730/460, current 361.366058/470: elapsed=167333.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.349304
last_received_ts = 361.349091
last_seq = 469
current_ts = 361.516663
current_received_ts = 361.516388
current_seq = 479
count = 36
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.349304/469, current 361.516663/479: elapsed=167331.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.366058
last_received_ts = 361.516449
last_seq = 470
current_ts = 361.533386
current_received_ts = 361.683777
current_seq = 480
count = 37
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.366058/470, current 361.533386/480: elapsed=167322.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.516663
last_received_ts = 361.516388
last_seq = 479
current_ts = 361.683960
current_received_ts = 361.683716
current_seq = 489
count = 37
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.516663/479, current 361.683960/489: elapsed=167324.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.533386
last_received_ts = 361.683777
last_seq = 480
current_ts = 361.700714
current_received_ts = 361.851105
current_seq = 490
count = 38
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.533386/480, current 361.700714/490: elapsed=167336.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.683960
last_received_ts = 361.683716
last_seq = 489
current_ts = 361.851257
current_received_ts = 361.850983
current_seq = 499
count = 38
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.683960/489, current 361.851257/499: elapsed=167288.0us expected=168043.8us +- 840.2us, error 0.4%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.700714
last_received_ts = 361.851105
last_seq = 490
current_ts = 361.867981
current_received_ts = 362.018188
current_seq = 500
count = 39
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.700714/490, current 361.867981/500: elapsed=167280.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 361.851257
last_received_ts = 361.850983
last_seq = 499
current_ts = 362.018524
current_received_ts = 362.018097
current_seq = 509
count = 39
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 361.851257/499, current 362.018524/509: elapsed=167256.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = flip
last_ts = 361.867981
last_received_ts = 362.018188
last_seq = 500
current_ts = 362.035248
current_received_ts = 362.185577
current_seq = 510
count = 40
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 361.867981/500, current 362.035248/510: elapsed=167251.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 362.018524
last_received_ts = 362.018097
last_seq = 509
current_ts = 362.185791
current_received_ts = 362.185486
current_seq = 519
count = 40
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 362.018524/509, current 362.185791/519: elapsed=167262.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = flip
last_ts = 362.035248
last_received_ts = 362.185577
last_seq = 510
current_ts = 362.202484
current_received_ts = 362.352814
current_seq = 520
count = 41
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 362.035248/510, current 362.202484/520: elapsed=167258.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 362.185791
last_received_ts = 362.185486
last_seq = 519
current_ts = 362.353027
current_received_ts = 362.352753
current_seq = 529
count = 41
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 362.185791/519, current 362.353027/529: elapsed=167248.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = flip
last_ts = 362.202484
last_received_ts = 362.352814
last_seq = 520
current_ts = 362.369751
current_received_ts = 362.520142
current_seq = 530
count = 42
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 362.202484/520, current 362.369751/530: elapsed=167263.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 362.353027
last_received_ts = 362.352753
last_seq = 529
current_ts = 362.520294
current_received_ts = 362.520081
current_seq = 539
count = 42
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 362.353027/529, current 362.520294/539: elapsed=167268.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = flip
last_ts = 362.369751
last_received_ts = 362.520142
last_seq = 530
current_ts = 362.537018
current_received_ts = 362.687347
current_seq = 540
count = 43
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 362.369751/530, current 362.537018/540: elapsed=167265.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 362.520294
last_received_ts = 362.520081
last_seq = 539
current_ts = 362.687561
current_received_ts = 362.687286
current_seq = 549
count = 43
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 362.520294/539, current 362.687561/549: elapsed=167261.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = flip
last_ts = 362.537018
last_received_ts = 362.687347
last_seq = 540
current_ts = 362.704285
current_received_ts = 362.854187
current_seq = 550
count = 44
seq_step = 1
(kms_flip:2495) DEBUG: flip ts/seq: last 362.537018/540, current 362.704285/550: elapsed=167247.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: name = vblank
last_ts = 362.687561
last_received_ts = 362.687286
last_seq = 549
current_ts = 362.854767
current_received_ts = 362.854156
current_seq = 559
count = 44
seq_step = 10
(kms_flip:2495) DEBUG: vblank ts/seq: last 362.687561/549, current 362.854767/559: elapsed=167206.0us expected=168043.8us +- 840.2us, error 0.5%
(kms_flip:2495) DEBUG: expected 448, counted 450, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 448, counted 450, encoder type 2
(kms_flip:2495) DEBUG: expected 448, counted 450, encoder type 2
(kms_flip:2495) DEBUG: dropped frames, expected 448, counted 450, encoder type 2
(kms_flip:2495) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2495) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2495) igt_core-INFO: Stack trace:
(kms_flip:2495) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2495) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2495) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2495) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2495) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2495) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2495) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2495) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A3: FAIL (11.205s)
Starting dynamic subtest: D-HDMI-A3
Dynamic subtest D-HDMI-A3: SUCCESS (7.958s)
Subtest flip-vs-blocking-wf-vblank: FAIL (35.406s)