Bug 102670

Summary: [CI] igt@kms_cursor_legacy@*flip-vs-cursor-* Failed assertion: get_vblank(display->drm_fd, pipe, 0) == *
Product: DRI Reporter: Marta Löfstedt <marta.lofstedt>
Component: IGTAssignee: Default DRI bug account <dri-devel>
Status: RESOLVED MOVED QA Contact:
Severity: major    
Priority: medium CC: arkadiusz.hiler, intel-gfx-bugs
Version: DRI git   
Hardware: Other   
OS: All   
Whiteboard: ReadyForDev
i915 platform: ALL i915 features: display/Other

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
Comment 18 Martin Peres 2019-11-12 07:38:10 UTC 
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/drm/igt-gpu-tools/issues/5.

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.