Re: [igt-dev] [PATCH i-g-t v2 1/2] tests/kms_cursor_crc: Change the way we collect crc's

[Daniel Vetter <daniel@ffwll.ch>]

On Tue, Jan 22, 2019 at 10:45:39AM +0000, Kahola, Mika wrote:
> On Tue, 2019-01-22 at 10:20 +0100, Daniel Vetter wrote:
> > On Thu, Jan 10, 2019 at 1:50 PM Mika Kahola <mika.kahola@intel.com>
> > wrote:
> > > 
> > > Instead of collecting crc's in one shot i.e. opening crc for
> > > reading,
> > > collecting crc and closing the file, let's start crc collection and
> > > keep
> > > collecting crc's until we are done. This fixes an issue that we
> > > occasionally read errornous crc, at least with ICL.
> > > 
> > > The bug can be replicated for example with
> > > 
> > > kms_cursor_crc --run-subtest cursor-64x64-onscreen
> > > 
> > > Starting subtest: cursor-64x64-onscreen
> > > Beginning cursor-64x64-onscreen on pipe A, connector eDP-1
> > > .(kms_cursor_crc:19282) igt-debugfs-CRITICAL: Test assertion
> > > failure function igt_assert_crc_equal, file igt_debugfs.c:419:
> > > (kms_cursor_crc:19282) igt-debugfs-CRITICAL: Failed assertion:
> > > !mismatch
> > > Stack trace:
> > >   #0 /home/testrunner/igt/lib/igt_core.c:1472 __igt_fail_assert()
> > >   #1 /home/testrunner/igt/lib/igt_debugfs.c:419
> > > igt_assert_crc_equal()
> > >   #2 /home/testrunner/igt/tests/kms_cursor_crc.c:213
> > > do_single_test()
> > >   #3 /home/testrunner/igt/tests/kms_cursor_crc.c:248 do_test()
> > >   #4 /home/testrunner/igt/tests/kms_cursor_crc.c:266
> > > test_crc_onscreen()
> > >   #5 /home/testrunner/igt/tests/kms_cursor_crc.c:433
> > > run_test.constprop.8()
> > >   #6 /home/testrunner/igt/tests/kms_cursor_crc.c:594
> > > run_test_generic.constprop.6()
> > >   #7 /home/testrunner/igt/tests/kms_cursor_crc.c:690
> > > __real_main656()
> > >   #8 /home/testrunner/igt/tests/kms_cursor_crc.c:656 main()
> > >   #9 ../csu/libc-start.c:344 __libc_start_main()
> > >   #10 [_start+0x2a]
> > > Subtest cursor-64x64-onscreen failed.
> > > **** DEBUG ****
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.2 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.2 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe B, plane 3
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe B,
> > > plane 3, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.3 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.3 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.3 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe B, plane 4
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe B,
> > > plane 4, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.4 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.4 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.4 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe B, plane 5
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe B,
> > > plane 5, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.5 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.5 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.5 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe B, plane 6
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe B,
> > > plane 6, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.6 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.6 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > B.6 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe B, plane 7
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetCursor pipe
> > > B, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     MoveCursor pipe
> > > B, (0, 0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetCrtc pipe C,
> > > disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 1, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.1 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.1 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.1 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 2
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 2, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.2 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.2 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.2 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 3
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 3, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.3 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.3 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.3 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 4
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 4, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.4 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.4 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.4 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 5
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 5, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.5 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.5 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.5 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 6
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetPlane pipe C,
> > > plane 6, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.6 "rotation" to 0x1/1
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.6 "COLOR_ENCODING" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetProp plane
> > > C.6 "COLOR_RANGE" to 0x0/0
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     Fixing up
> > > initial rotation pipe C, plane 7
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetCursor pipe
> > > C, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     MoveCursor pipe
> > > C, (0, 0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: }
> > > (kms_cursor_crc:19282) igt-debugfs-DEBUG: Opening debugfs directory
> > > '/sys/kernel/debug/dri/0'
> > > (kms_cursor_crc:19282) igt-debugfs-DEBUG: Opening debugfs directory
> > > '/sys/kernel/debug/dri/0'
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: Test requirement passed:
> > > plane_idx >= 0 && plane_idx < pipe->n_planes
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_fb(0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_size
> > > (0x0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_position(0,0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_size(0x0)
> > > (kms_cursor_crc:19282) INFO: Beginning cursor-64x64-onscreen on
> > > pipe A, connector eDP-1
> > > (kms_cursor_crc:19282) igt-fb-DEBUG: Test requirement passed:
> > > cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: Test requirement passed:
> > > plane_idx >= 0 && plane_idx < pipe->n_planes
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > plane_set_fb(227)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_size
> > > (64x65)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_position(0,0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_size(64x65)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_size
> > > (64x64)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: Test requirement passed:
> > > plane_idx >= 0 && plane_idx < pipe->n_planes
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > plane_set_position(0,0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: commit {
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetCursor pipe
> > > A, fb 1 64x64
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     MoveCursor pipe
> > > A, (0, 0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: }
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: Test requirement passed:
> > > plane_idx >= 0 && plane_idx < pipe->n_planes
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_fb(0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7: plane_set_size
> > > (0x0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_position(0,0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: A.7:
> > > fb_set_size(0x0)
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: commit {
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display:     SetCursor pipe
> > > A, disabling
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: }
> > > (kms_cursor_crc:19282) igt-fb-DEBUG: Test requirement passed:
> > > cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: commit {
> > > (kms_cursor_crc:19282) igt-kms-DEBUG: display: }
> > > (kms_cursor_crc:19282) igt-debugfs-DEBUG: CRC mismatch at index 0:
> > > 0x2e212a16 != 0x9245e25c
> > > (kms_cursor_crc:19282) igt-debugfs-CRITICAL: Test assertion failure
> > > function igt_assert_crc_equal, file igt_debugfs.c:419:
> > > (kms_cursor_crc:19282) igt-debugfs-CRITICAL: Failed assertion:
> > > !mismatch
> > > (kms_cursor_crc:19282) igt-core-INFO: Stack trace:
> > > (kms_cursor_crc:19282) igt-core-INFO:   #0
> > > /home/testrunner/igt/lib/igt_core.c:1472 __igt_fail_assert()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #1
> > > /home/testrunner/igt/lib/igt_debugfs.c:419 igt_assert_crc_equal()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #2
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:213 do_single_test()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #3
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:248 do_test()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #4
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:266 test_crc_onscreen()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #5
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:433
> > > run_test.constprop.8()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #6
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:594
> > > run_test_generic.constprop.6()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #7
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:690 __real_main656()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #8
> > > /home/testrunner/igt/tests/kms_cursor_crc.c:656 main()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #9 ../csu/libc-start.c:344
> > > __libc_start_main()
> > > (kms_cursor_crc:19282) igt-core-INFO:   #10 [_start+0x2a]
> > > ****  END  ****
> > > 
> > > v2: Stop collecting crc's after test completion
> > > 
> > > Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=103232
> > > Signed-off-by: Mika Kahola <mika.kahola@intel.com>
> > 
> > If this indeed fixes crc collection, or at least greatly improves it,
> > then we need this w/a in the kernel, not userspace. A possible
> > implementation idea:
> > - Don't disable crc for icl (maybe also gen9+, these crc issues are
> > that old) when userspace asks for it, just disable crc reporting
> > using
> > some per-crtc boolean.
> > - When re-enabling the crc collection with the same config, just
> > clear
> > the buffer (to make sure) and then succeed.
> > - Insert a pile of waits every time we enable crc for the first time,
> > to get the same effect.
> > 
> > We can't add these hacks to all the testcases to work around issues
> > on
> > one specific platform. The kernel's debugfs abstraction should take
> > care of this. A quick hack to remove the crc disabling and clear the
> > crc buffer on re-enabling should be all you need to prove this (it'll
> > result in some noise due to crc buffer overruns, and it might anger
> > the hw because of the reprogramming, but I don't expect that).
> > 
> > Another thing that I think we need to debug this: Better fifo
> > underrun
> > reporting statistics. Currently fifo underruns are single-shot, see:
> > 
> > 
> https://dri.freedesktop.org/docs/drm/gpu/i915.html#display-fifo-underrun-reporting
> > 
> > First step would be a debug option (module or debugfs or whatever) to
> > disable the fifo underrun reporting after the first error. That way
> > we
> > can measure whether things get better or worse if something changes,
> > atm we only have a binary answer (and hence no way to tell whether
> > we're moving forward). This is for all the cases where fifo underruns
> > come together with CRC mismatches. Long-term we probably want some
> > basic statistics (report the # of fifo underruns per second), plus a
> > failsafe to disable the fifo underrun if that number is too high and
> > we're just hogging the cpu. More than 10k interrupts/s is probably
> > too
> > much, even for debugging.
> > -Daniel
> 
> With this approach it turned out that this works only for skl+
> platforms. Older gens would need original way of crc collection. It
> puzzles me a bit how two different approaches, which ultimately should
> produce the same outcome, actually behaves differently. I think this
> patch would propably just hide the real issue in kernel and we need to
> dig deeper. 

Yeah, my suggestion would be that if we indeed need this for skl+, then we
should do it in-kernel, but _only_ for skl+ crc support. And leave the
current crc support for older platforms unchanged.

Also yeah I'm baffled that this would break crc for older machines ... do
you have examples?

> Like you said, let's go back on debugging the kernel. I will try to
> change the fifo underrun reporting to something else than single-shot.
> I faintly remember that we did this single-shot approach to minimize
> the noise in dmesg.
> 
> Thanks for useful tips and hints!

I think with all these crc/fifo underrun issues first step is to get
better data (we seem to be running around blind), hence the suggestion to
resurrect the fifo underrun statistics. Iirc our intel cros team has
hacked something like this together already for improving the skl wm way
back when skl was dying constantly because of fifo underruns.
-Daniel

> 
> Cheers,
> Mika 
> 
> > 
> > 
> > > ---
> > >  tests/kms_cursor_crc.c | 8 +++++---
> > >  1 file changed, 5 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/tests/kms_cursor_crc.c b/tests/kms_cursor_crc.c
> > > index 1514e7f2..83dbe0b7 100644
> > > --- a/tests/kms_cursor_crc.c
> > > +++ b/tests/kms_cursor_crc.c
> > > @@ -172,7 +172,8 @@ static void do_single_test(data_t *data, int x,
> > > int y)
> > >         igt_display_commit(display);
> > > 
> > >         igt_wait_for_vblank(data->drm_fd, data->pipe);
> > > -       igt_pipe_crc_collect_crc(pipe_crc, &crc);
> > > +       igt_pipe_crc_start(pipe_crc);
> > > +       igt_pipe_crc_get_single(pipe_crc, &crc);
> > > 
> > >         if (data->flags & (TEST_DPMS | TEST_SUSPEND)) {
> > >                 igt_crc_t crc_after;
> > > @@ -191,7 +192,7 @@ static void do_single_test(data_t *data, int x,
> > > int y)
> > >                         igt_system_suspend_autoresume(SUSPEND_STATE
> > > _MEM,
> > >                                                       SUSPEND_TEST_
> > > NONE);
> > > 
> > > -               igt_pipe_crc_collect_crc(pipe_crc, &crc_after);
> > > +               igt_pipe_crc_get_current(data->drm_fd, pipe_crc,
> > > &crc_after);
> > >                 igt_assert_crc_equal(&crc, &crc_after);
> > >         }
> > > 
> > > @@ -205,8 +206,9 @@ static void do_single_test(data_t *data, int x,
> > > int y)
> > >         igt_display_commit(display);
> > > 
> > >         igt_wait_for_vblank(data->drm_fd, data->pipe);
> > > -       igt_pipe_crc_collect_crc(pipe_crc, &ref_crc);
> > > +       igt_pipe_crc_get_current(data->drm_fd, pipe_crc, &ref_crc);
> > >         igt_assert_crc_equal(&crc, &ref_crc);
> > > +       igt_pipe_crc_stop(pipe_crc);
> > > 
> > >         /* Clear screen afterwards */
> > >         cr = igt_get_cairo_ctx(data->drm_fd, &data->primary_fb);
> > > --
> > > 2.17.1
> > > 
> > > _______________________________________________
> > > igt-dev mailing list
> > > igt-dev@lists.freedesktop.org
> > > https://lists.freedesktop.org/mailman/listinfo/igt-dev
> > 
> > 
> > 

-- 
Daniel Vetter
Software Engineer, Intel Corporation
http://blog.ffwll.ch
_______________________________________________
igt-dev mailing list
igt-dev@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/igt-dev