Bug 102670 - [CI] igt@kms_cursor_legacy@*flip-vs-cursor-* Failed assertion: get_vblank(display->drm_fd, pipe, 0) == *
Summary: [CI] igt@kms_cursor_legacy@*flip-vs-cursor-* Failed assertion: get_vblank(dis...
Status: NEW
Alias: None
Product: DRI
Classification: Unclassified
Component: IGT (show other bugs)
Version: DRI git
Hardware: Other All
: medium major
Assignee: Default DRI bug account
QA Contact:
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2017-09-12 07:11 UTC by Marta Löfstedt
Modified: 2019-04-11 11:20 UTC (History)
2 users (show)

See Also:
i915 platform: ALL
i915 features: display/Other


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Marta Löfstedt 2017-09-12 07:11:34 UTC
On CI_DRM_3074 HSW-shard:  

(kms_cursor_legacy:1579) CRITICAL: Test assertion failure function flip_vs_cursor, file kms_cursor_legacy.c:833:
(kms_cursor_legacy:1579) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:1579) CRITICAL: error: 1068 != 1067
Subtest flip-vs-cursor-toggle failed.


https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3074/shard-hsw1/igt@kms_cursor_legacy@flip-vs-cursor-toggle.html
Comment 1 Jani Saarinen 2017-09-14 08:17:27 UTC
This has failed only once so far. And based on priority drop it major.
Comment 2 Marta Löfstedt 2017-09-19 12:50:04 UTC
Now also on the igt@kms_cursor_legacy@flip-vs-cursor-legacy

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3104/shard-hsw5/igt@kms_cursor_legacy@flip-vs-cursor-legacy.html
Comment 5 Marta Löfstedt 2017-11-15 07:18:41 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3345/shard-hsw5/igt@kms_cursor_legacy@flip-vs-cursor-varying-size.html

(kms_cursor_legacy:4316) CRITICAL: Test assertion failure function flip_vs_cursor, file kms_cursor_legacy.c:747:
(kms_cursor_legacy:4316) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:4316) CRITICAL: error: 22978 != 22977
Subtest flip-vs-cursor-varying-size failed.
Comment 6 Marta Löfstedt 2017-11-22 07:01:33 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3368/shard-apl7/igt@kms_cursor_legacy@basic-flip-after-cursor-varying-size.html

(kms_cursor_legacy:7572) CRITICAL: Test assertion failure function basic_flip_cursor, file kms_cursor_legacy.c:525:
(kms_cursor_legacy:7572) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start
(kms_cursor_legacy:7572) CRITICAL: error: 35891 != 35889
Subtest basic-flip-after-cursor-varying-size failed.
Comment 7 Marta Löfstedt 2017-12-11 07:49:16 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3495/shard-snb5/igt@kms_cursor_legacy@flip-vs-cursor-toggle.html


(kms_cursor_legacy:1351) CRITICAL: Test assertion failure function flip_vs_cursor, file kms_cursor_legacy.c:747:
(kms_cursor_legacy:1351) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:1351) CRITICAL: error: 1148 != 1147
Subtest flip-vs-cursor-toggle failed.
Comment 8 Marta Löfstedt 2018-01-17 07:24:59 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4141/shard-apl1/igt@kms_cursor_legacy@short-flip-after-cursor-atomic-transitions-varying-size.html

(kms_cursor_legacy:1786) CRITICAL: Test assertion failure function basic_flip_cursor, file kms_cursor_legacy.c:525:
(kms_cursor_legacy:1786) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start
(kms_cursor_legacy:1786) CRITICAL: error: 8766 != 8765
Subtest short-flip-after-cursor-atomic-transitions-varying-size failed.
Comment 9 Marta Löfstedt 2018-01-25 06:50:53 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3683/shard-apl7/igt@kms_cursor_legacy@flip-vs-cursor-crc-atomic.html

(kms_cursor_legacy:2734) CRITICAL: Test assertion failure function flip_vs_cursor_crc, file kms_cursor_legacy.c:1259:
(kms_cursor_legacy:2734) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:2734) CRITICAL: error: 7789 != 7787
Subtest flip-vs-cursor-crc-atomic failed.
Comment 10 Marta Löfstedt 2018-03-21 10:45:50 UTC
This issue has only been reproduced on HSW-shards within reasonable time. I cleared out some impact from cibuglog.
Comment 11 Marta Löfstedt 2018-03-26 12:51:55 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_7/fi-skl-6770hq/igt@kms_cursor_legacy@flip-vs-cursor-toggle.html

(kms_cursor_legacy:1947) CRITICAL: Test assertion failure function flip_vs_cursor, file ../tests/kms_cursor_legacy.c:746:
(kms_cursor_legacy:1947) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:1947) CRITICAL: error: 9723 != 9722
Subtest flip-vs-cursor-toggle failed.
Comment 12 Marta Löfstedt 2018-03-27 09:48:06 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_7/fi-cfl-s3/igt@kms_cursor_legacy@flip-vs-cursor-legacy.html

(kms_cursor_legacy:2984) CRITICAL: Test assertion failure function flip_vs_cursor, file ../tests/kms_cursor_legacy.c:738:
(kms_cursor_legacy:2984) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start
(kms_cursor_legacy:2984) CRITICAL: error: 6101 != 6100
Subtest flip-vs-cursor-legacy failed.
Comment 13 Marta Löfstedt 2018-03-28 06:22:56 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3986/shard-hsw4/igt@kms_cursor_legacy@flip-vs-cursor-crc-atomic.html

(kms_cursor_legacy:6438) CRITICAL: Test assertion failure function flip_vs_cursor_crc, file ../tests/kms_cursor_legacy.c:1259:
(kms_cursor_legacy:6438) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) == vblank_start + 1
(kms_cursor_legacy:6438) CRITICAL: error: 28717 != 28716
Subtest flip-vs-cursor-crc-atomic failed.
Comment 14 Francesco Balestrieri 2018-06-19 12:45:18 UTC
Marteen, are you looking at this?
Comment 15 Jani Saarinen 2018-08-08 11:26:05 UTC
Lowering priority, low occurrence
Comment 16 Lakshmi 2018-11-23 14:31:34 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_146/fi-gdg-551/igt@kms_cursor_legacy@flip-vs-cursor-toggle.html

Starting subtest: flip-vs-cursor-toggle
(kms_cursor_legacy:1103) CRITICAL: Test assertion failure function flip_vs_cursor, file ../tests/kms_cursor_legacy.c:741:
(kms_cursor_legacy:1103) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) <= vblank_start + 1
(kms_cursor_legacy:1103) CRITICAL: error: 4631 > 4630
Subtest flip-vs-cursor-toggle failed.
**** DEBUG ****
(kms_cursor_legacy:1103) DEBUG: Test requirement passed: found
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: VGA-1: set_pipe(A)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: VGA-1: Selecting pipe A
(kms_cursor_legacy:1103) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=0x34325258, tiling=0x0, size=0)
(kms_cursor_legacy:1103) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096)
(kms_cursor_legacy:1103) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_cursor_legacy:1103) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.0: plane_set_fb(42)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.0: plane_set_size (1024x768)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.0: fb_set_position(0,0)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.0: fb_set_size(1024x768)
(kms_cursor_legacy:1103) DEBUG: Test requirement passed: set_fb_on_crtc(display, pipe, &fb_info)
(kms_cursor_legacy:1103) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=64, height=64, format=0x34325241, tiling=0x0, size=0)
(kms_cursor_legacy:1103) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=256)
(kms_cursor_legacy:1103) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_cursor_legacy:1103) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_cursor_legacy:1103) DEBUG: Test requirement passed: cursor
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.1: plane_set_fb(51)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.1: plane_set_size (64x64)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.1: fb_set_position(0,0)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: A.1: fb_set_size(64x64)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: commit {
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     VGA-1: SetCrtc pipe A, fb 42, src (0, 0), mode 1024x768
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     SetCursor pipe A, fb 2 64x64
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     MoveCursor pipe A, (0, 0)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     SetCrtc pipe B, disabling
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     SetCursor pipe B, disabling
(kms_cursor_legacy:1103) igt_kms-DEBUG: display:     MoveCursor pipe B, (0, 0)
(kms_cursor_legacy:1103) igt_kms-DEBUG: display: }
(kms_cursor_legacy:1103) igt_debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
(kms_cursor_legacy:1103) DEBUG: Test requirement passed: target > 1
(kms_cursor_legacy:1103) DEBUG: Using a target of 32 cursor updates per quarter-vblank
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) igt_kms-DEBUG: Test requirement passed: plane_idx >= 0 && plane_idx < pipe->n_planes
(kms_cursor_legacy:1103) CRITICAL: Test assertion failure function flip_vs_cursor, file ../tests/kms_cursor_legacy.c:741:
(kms_cursor_legacy:1103) CRITICAL: Failed assertion: get_vblank(display->drm_fd, pipe, 0) <= vblank_start + 1
(kms_cursor_legacy:1103) CRITICAL: error: 4631 > 4630
(kms_cursor_legacy:1103) igt_core-INFO: Stack trace:
(kms_cursor_legacy:1103) igt_core-INFO:   #0 ../lib/igt_core.c:1467 __igt_fail_assert()
(kms_cursor_legacy:1103) igt_core-INFO:   #1 ../tests/kms_cursor_legacy.c:743 flip_vs_cursor()
(kms_cursor_legacy:1103) igt_core-INFO:   #2 ../tests/kms_cursor_legacy.c:1494 __real_main1358()
(kms_cursor_legacy:1103) igt_core-INFO:   #3 ../tests/kms_cursor_legacy.c:1358 main()
(kms_cursor_legacy:1103) igt_core-INFO:   #4 ../csu/libc-start.c:344 __libc_start_main()
(kms_cursor_legacy:1103) igt_core-INFO:   #5 [_start+0x2a]
****  END  ****
Subtest flip-vs-cursor-toggle: FAIL (13.472s)
Comment 17 Arek Hiler 2019-04-11 11:20:24 UTC
The test seems to be very prone to race conditions and this may explain the sporadic failures we see (few instances every week, affects all the machines):

1. we try to figure out experimentally how many cursor updates we can squeeze between vblanks, by starting with a high number and lowering it until we fit. Our target is a quarter of that
2. we pin our process to a CPU and fork a busy loop with sched_yield();
3. 150 loops of trying to squeeze target cursor updates within one vblank

This doesn't take power and thermal budged into account and makes a lot of assumptions about process scheduling on a non-RTOS.

User impact is low. We loose some coverage. Test needs to be reworked.

Immediate steps:
1. log the delta between vblanks, so we can regain some coverage by having better filters
2. log our target
3. don't exit early, show how many iterations of the 150 had failed

This is related and it makes sense to work on both together: https://bugs.freedesktop.org/show_bug.cgi?id=103355


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.