Bug 103355 - [CI][SHARDS] igt@kms_cursor_legacy@cursor-vs-flip-* - fail - Failed assertion: shared[0] > vrefresh*target / 2
Summary: [CI][SHARDS] igt@kms_cursor_legacy@cursor-vs-flip-* - fail - Failed assertion...
Status: REOPENED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: low normal
Assignee: anusha
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2017-10-19 07:58 UTC by Marta Löfstedt
Modified: 2019-04-16 12:39 UTC (History)
2 users (show)

See Also:
i915 platform: HSW, ICL, KBL, SKL
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-10-19 07:58:59 UTC
GLK- APL-shards 
	

(kms_cursor_legacy:2891) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:2891) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:2891) CRITICAL: completed 947 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-toggle failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3259/shard-glkb5/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3260/shard-apl1/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3261/shard-glkb3/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html
Comment 1 Marta Löfstedt 2017-10-25 06:48:10 UTC
APL-shards CI_DRM_3277 igt@kms_cursor_legacy@cursor-vs-flip-atomic

(kms_cursor_legacy:5583) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:5583) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:5583) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_cursor_legacy:5583) CRITICAL: completed 836 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-atomic failed.

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3277/shard-apl6/igt@kms_cursor_legacy@cursor-vs-flip-atomic.html
Comment 2 Marta Löfstedt 2017-11-09 11:22:16 UTC
new subtest:
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3324/shard-glkb1/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions.html

(kms_cursor_legacy:7212) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:7212) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:7212) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_cursor_legacy:7212) CRITICAL: completed 2836 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-atomic-transitions failed.
Comment 3 Marta Löfstedt 2017-11-17 11:58:39 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3356/shard-glkb4/igt@kms_cursor_legacy@cursor-vs-flip-varying-size.html

(kms_cursor_legacy:13431) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:13431) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:13431) CRITICAL: completed 1456 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-varying-size failed.
Comment 4 Marta Löfstedt 2017-11-17 11:59:29 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3356/shard-apl6/igt@kms_cursor_legacy@cursor-vs-flip-varying-size.html

(kms_cursor_legacy:4401) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:4401) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:4401) CRITICAL: completed 819 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-varying-size failed.
Comment 5 Marta Löfstedt 2017-11-20 10:44:51 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGTPW_502/shard-apl4/igt@kms_cursor_legacy@cursor-vs-flip-legacy.html

(kms_cursor_legacy:1786) CRITICAL: Test assertion failure function cursor_vs_flip, file kms_cursor_legacy.c:1066:
(kms_cursor_legacy:1786) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1786) CRITICAL: completed 880 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-legacy failed.
Comment 7 Marta Löfstedt 2018-03-16 09:29:36 UTC
Last seen:  CI_DRM_3754: 2018-02-12 / 280 runs ago
Comment 8 Martin Peres 2018-03-24 06:42:23 UTC
Now also on HSW: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_3977/shard-hsw3/igt@kms_cursor_legacy@cursor-vs-flip-varying-size.html

(kms_cursor_legacy:1416) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1100:
(kms_cursor_legacy:1416) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1416) CRITICAL: completed 7404 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-varying-size failed.
Comment 9 Marta Löfstedt 2018-04-06 05:51:37 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4025/shard-hsw3/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html

(kms_cursor_legacy:2541) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1100:
(kms_cursor_legacy:2541) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:2541) CRITICAL: completed 7542 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-toggle failed.
Comment 10 Martin Peres 2018-04-09 12:33:49 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4417_full/shard-kbl4/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html

(kms_cursor_legacy:1384) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1100:
(kms_cursor_legacy:1384) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1384) CRITICAL: completed 7581 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-toggle failed.
Comment 11 Martin Peres 2018-05-03 16:12:45 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_30/fi-kbl-7560u/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html

(kms_cursor_legacy:1727) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1100:
(kms_cursor_legacy:1727) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1727) CRITICAL: completed 7105 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-toggle failed.
Comment 12 Martin Peres 2018-08-30 15:25:32 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_89/fi-bdw-5557u/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html

(kms_cursor_legacy:1338) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1101:
(kms_cursor_legacy:1338) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1338) CRITICAL: completed 7240 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-toggle failed.
Comment 13 Martin Peres 2018-12-17 17:21:15 UTC
Also seen on ICL: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5324/shard-iclb3/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions-varying-size.html

Starting subtest: cursor-vs-flip-atomic-transitions-varying-size
(kms_cursor_legacy:5035) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1101:
(kms_cursor_legacy:5035) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:5035) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_cursor_legacy:5035) CRITICAL: completed 1222 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-atomic-transitions-varying-size failed.
Comment 14 Martin Peres 2018-12-17 17:21:53 UTC
More issues on ICL: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5317/shard-iclb3/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions-varying-size.html

Starting subtest: cursor-vs-flip-atomic-transitions-varying-size
(kms_cursor_legacy:4834) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1101:
(kms_cursor_legacy:4834) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:4834) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_cursor_legacy:4834) CRITICAL: completed 1260 cursor updated in a period of 30 flips, we expect to complete approximately 7680 updates, with the threshold set at 3840
Subtest cursor-vs-flip-atomic-transitions-varying-size failed.
Comment 15 Martin Peres 2018-12-17 17:31:32 UTC
Also seen on WHL and SKL:

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_172/fi-skl-6770hq/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions.html

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_172/fi-skl-6770hq/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions-varying-size.html

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_171/fi-whl-u/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions-varying-size.html

https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_171/fi-whl-u/igt@kms_cursor_legacy@cursor-vs-flip-atomic-transitions.html

Starting subtest: cursor-vs-flip-atomic-transitions
(kms_cursor_legacy:1344) CRITICAL: Test assertion failure function cursor_vs_flip, file ../tests/kms_cursor_legacy.c:1101:
(kms_cursor_legacy:1344) CRITICAL: Failed assertion: shared[0] > vrefresh*target / 2
(kms_cursor_legacy:1344) CRITICAL: Last errno: 25, Inappropriate ioctl for device
(kms_cursor_legacy:1344) CRITICAL: completed 1784 cursor updated in a period of 30 flips, we expect to complete approximately 15360 updates, with the threshold set at 7680
Subtest cursor-vs-flip-atomic-transitions failed.
Comment 16 CI Bug Log 2018-12-31 10:20:18 UTC
A CI Bug Log filter associated to this bug has been updated:

{- HSW APL SKL KBL GLK WHL ICL: kms_cursor_legacy@cursor-vs-flip.* - Failed assertion: shared[0] > vrefresh*target / 2 -}
{+ GDG HSW APL SKL KBL GLK WHL ICL: kms_cursor_legacy@cursor-vs-flip.* - Failed assertion: shared[0] > vrefresh*target / 2 +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_176/fi-gdg-551/igt@kms_cursor_legacy@cursor-vs-flip-toggle.html
Comment 17 Martin Peres 2019-04-03 07:19:57 UTC
Updating the platforms, and assigning Anusha since she started investigating this. Please update this bug with your progress :)
Comment 18 Arek Hiler 2019-04-03 07:26:40 UTC
The test is checking how many cursor updates we can fit between vblanks, and treating that as a baseline. Then it does 30 flips and checks whether we fit expected (num_of_flips * baseline / 8) amount of cursor updates. The check is done 50 times.

We fails this check but yet the cursor refresh rate for each failure is well above 1k (per 30 flips) and there are really no sense in having mouses with refresh rates higher than 1kHz.

The customer impact is low.

The test needs some rethinking and possibly updated pass criteria.
Comment 19 Martin Peres 2019-04-03 07:28:47 UTC
(In reply to Arek Hiler from comment #18)
> The test is checking how many cursor updates we can fit between vblanks, and
> treating that as a baseline. Then it does 30 flips and checks whether we fit
> expected (num_of_flips * baseline / 8) amount of cursor updates. The check
> is done 50 times.
> 
> We fails this check but yet the cursor refresh rate for each failure is well
> above 1k (per 30 flips) and there are really no sense in having mouses with
> refresh rates higher than 1kHz.
> 
> The customer impact is low.
> 
> The test needs some rethinking and possibly updated pass criteria.

Anusha, please update the test to clip the wanted refresh rate to 1kHz, anything above above is useless and just adds noise.
Comment 20 anusha 2019-04-04 05:55:20 UTC
(In reply to Martin Peres from comment #19)
> (In reply to Arek Hiler from comment #18)
> > The test is checking how many cursor updates we can fit between vblanks, and
> > treating that as a baseline. Then it does 30 flips and checks whether we fit
> > expected (num_of_flips * baseline / 8) amount of cursor updates. The check
> > is done 50 times.
> > 
> > We fails this check but yet the cursor refresh rate for each failure is well
> > above 1k (per 30 flips) and there are really no sense in having mouses with
> > refresh rates higher than 1kHz.
> > 
> > The customer impact is low.
> > 
> > The test needs some rethinking and possibly updated pass criteria.
> 
> Anusha, please update the test to clip the wanted refresh rate to 1kHz,
> anything above above is useless and just adds noise.

I dont think that will work. The test checks that a certain amount (targeteted amount) of cursor updates happens between vblanks and that flip do not affect vblank counter. The subtest already sets the targetted cursor updates to a pretty low value, despite that the test fails.  We need to understand -
1. how the flips are affecting the vblanks
2. why particularly in ICL we are not able to do that many number of cursor updates. (that is assuming this test was passing on non ICL systems). I plan on seeing the behaviour on my KBL system.

Also, just out of curiosity I did change the target value to see if at any point the test passes. it doesnt. Regardless of how less we set the cursor update, we fail to achieve that in the given interval.
Comment 21 Arek Hiler 2019-04-04 13:02:19 UTC
(In reply to anusha from comment #20)
> I dont think that will work. The test checks that a certain amount
> (targeteted amount) of cursor updates happens between vblanks and that flip
> do not affect vblank counter. The subtest already sets the targetted cursor
> updates to a pretty low value, despite that the test fails.  We need to
> understand -
> 1. how the flips are affecting the vblanks
> 2. why particularly in ICL we are not able to do that many number of cursor
> updates. (that is assuming this test was passing on non ICL systems). I plan
> on seeing the behaviour on my KBL system.
> 
> Also, just out of curiosity I did change the target value to see if at any
> point the test passes. it doesnt. Regardless of how less we set the cursor
> update, we fail to achieve that in the given interval.

Hey,

Just to be sure that I understand the test correctly:
1. we fork and do DRM_IOCTL_MODE_CURSOR in a "busy" loop
2. we wait for 30 flips (vrefresh/2, vrefresh=60)
3. we check how many MODE_CURSOR have succeeded
4. we compare the number of times we managed to call the IOCTL vs our target*30

Currently the "target" comes from get_cursor_updates_per_vblank() which from the number of MODE_CURSOR ioctl we manage to squeeze in between two vblanks divided by 8.

We have seen a lot of failures where the target was not hit, but still all of them managed to do about 1.5k cursor updates in that time, which means about 3kHz cursor update rate, which is plenty.

That would mean if we have over 500 updates in that 30 frame window (0.5s) we would hit the 1kHz requirement.

What am I missing in this reasoning?
Comment 22 anusha 2019-04-04 16:51:46 UTC
(In reply to Arek Hiler from comment #21)
> (In reply to anusha from comment #20)
> > I dont think that will work. The test checks that a certain amount
> > (targeteted amount) of cursor updates happens between vblanks and that flip
> > do not affect vblank counter. The subtest already sets the targetted cursor
> > updates to a pretty low value, despite that the test fails.  We need to
> > understand -
> > 1. how the flips are affecting the vblanks
> > 2. why particularly in ICL we are not able to do that many number of cursor
> > updates. (that is assuming this test was passing on non ICL systems). I plan
> > on seeing the behaviour on my KBL system.
> > 
> > Also, just out of curiosity I did change the target value to see if at any
> > point the test passes. it doesnt. Regardless of how less we set the cursor
> > update, we fail to achieve that in the given interval.
> 
> Hey,
> 
> Just to be sure that I understand the test correctly:
> 1. we fork and do DRM_IOCTL_MODE_CURSOR in a "busy" loop
> 2. we wait for 30 flips (vrefresh/2, vrefresh=60)
> 3. we check how many MODE_CURSOR have succeeded
> 4. we compare the number of times we managed to call the IOCTL vs our
> target*30
> 
> Currently the "target" comes from get_cursor_updates_per_vblank() which from
> the number of MODE_CURSOR ioctl we manage to squeeze in between two vblanks
> divided by 8.
> 
> We have seen a lot of failures where the target was not hit, but still all
> of them managed to do about 1.5k cursor updates in that time, which means
> about 3kHz cursor update rate, which is plenty.
> 
> That would mean if we have over 500 updates in that 30 frame window (0.5s)
> we would hit the 1kHz requirement.
> 
> What am I missing in this reasoning?

Yes. that is how I have understood it too. In the D stepping that I am using, we are  doing only about 1350 updates max. I tried to play around with reducing the threshold just to see at what point the test passes and the lesser we reduce the  threshold value to, the lesser updates we are doing. Which is very weird....
Comment 23 Arek Hiler 2019-04-05 06:48:39 UTC
(In reply to anusha from comment #22)
> I tried to play around with reducing the threshold just to see at
> what point the test passes and the lesser we reduce the threshold
> value to, the lesser updates we are doing. Which is very weird....

Interesting. 'target' does not play any role in the test other than
serving as the baseline for comparison at the very end of an iteration.

The only thing that comes to my mind is that cursor gets progressively
slower. Can you check that, as I don't have ICL at hands?

We do nloops=50 of iterations for cursor-vs-flip. You can turn the
igt_assert_f() to an igt_debug() and see how the shared[0], which
has the number of performed updates, changes over the course
of execution.

Thanks!
Comment 24 Arek Hiler 2019-04-16 12:39:59 UTC
https://patchwork.freedesktop.org/series/59577/

to get some more data on passes and fails


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.