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

Submitted by Kahola, Mika on Jan. 10, 2019, 12:51 p.m.

Details

Message ID 20190110125125.26374-2-mika.kahola@intel.com
State New
Headers show
Series "tests/kms_cursor_crc: Change crc collection" ( rev: 4 3 ) in IGT

Not browsing as part of any series.

Commit Message

Kahola, Mika Jan. 10, 2019, 12:51 p.m.
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>
---
 tests/kms_cursor_crc.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

Patch hide | download patch | download mbox

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);

Comments

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


> ---
>  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
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. 

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!

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
> 
> 
>
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
> > 
> > 
> >
On Tue, 2019-01-22 at 14:20 +0100, Daniel Vetter wrote:
> 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?

Well, I managed to trigger it once on my hsw with the test

kms_cursor_crc --run-subtest cursor-64x64x-onscreen.

Now, when I'm trying to trigger it again to get the dmesg of a failing
test, I'm unable to do so.

CI runs with this patch set were clean. Because of this earlier mishap,
I was left with the doubt that we shouldn't do this for older
platforms.

> 
> > 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.
Do they have patches available for this that could be shared?

> -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_S
> > > > TATE
> > > > _MEM,
> > > >                                                       SUSPEND_T
> > > > EST_
> > > > 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
> > > 
> > > 
> > > 
> 
>
On Tue, Jan 22, 2019 at 2:53 PM Kahola, Mika <mika.kahola@intel.com> wrote:
>
> On Tue, 2019-01-22 at 14:20 +0100, Daniel Vetter wrote:
> > 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?
>
> Well, I managed to trigger it once on my hsw with the test
>
> kms_cursor_crc --run-subtest cursor-64x64x-onscreen.
>
> Now, when I'm trying to trigger it again to get the dmesg of a failing
> test, I'm unable to do so.
>
> CI runs with this patch set were clean. Because of this earlier mishap,
> I was left with the doubt that we shouldn't do this for older
> platforms.
>
> >
> > > 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.
> Do they have patches available for this that could be shared?

I couldn't find them anymore, but it amounted to not disabling fifo
underrun reporting every time we hit a fifo underrun. Shouldn't be
much work to recreate that one.
-Daniel

>
> > -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_S
> > > > > TATE
> > > > > _MEM,
> > > > >                                                       SUSPEND_T
> > > > > EST_
> > > > > 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
> > > >
> > > >
> > > >
> >
> >