Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Thu, 3 Nov 2022 12:40:59 +0100
From:   Mauro Carvalho Chehab <mauro.chehab@linux.intel.com>
To:     Isabella Basso <isabbasso@riseup.net>
Cc:     igt-dev@lists.freedesktop.org, linux-kselftest@vger.kernel.org,
        daniel@ffwll.ch, kunit-dev@googlegroups.com,
        magalilemes00@gmail.com, maira.canal@usp.br, dlatypov@google.com,
        n@nfraprado.net, linux-kernel@vger.kernel.org,
        leandro.ribeiro@collabora.com, dri-devel@lists.freedesktop.org,
        davidgow@google.com, tales.aparecida@gmail.com,
        skhan@linuxfoundation.org, andrealmeid@riseup.net,
        brendanhiggins@google.com, twoerner@gmail.com
Subject: Re: [igt-dev] [PATCH i-g-t v2 3/4] lib/igt_kmod: add compatibility
 for KUnit
Message-ID: <20221103124059.682e7adf@maurocar-mobl2>
In-Reply-To: <20221103104840.7301df76@maurocar-mobl2>
References: <20220829000920.38185-1-isabbasso@riseup.net>
        <20220829000920.38185-4-isabbasso@riseup.net>
        <20221103104840.7301df76@maurocar-mobl2>
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Precedence: bulk

On Thu, 3 Nov 2022 10:48:40 +0100
Mauro Carvalho Chehab <mauro.chehab@linux.intel.com> wrote:

> On Sun, 28 Aug 2022 21:09:19 -0300
> Isabella Basso <isabbasso@riseup.net> wrote:
> 
> > This adds functions for both executing the tests as well as parsing (K)TAP
> > kmsg output, as per the KTAP spec [1].
> > 
> > [1] https://www.kernel.org/doc/html/latest/dev-tools/ktap.html
> > 
> > Signed-off-by: Isabella Basso <isabbasso@riseup.net>  
> 
> Hi Isabella,
> 
> I'm doing some tests here with my i915 KUnit patch series.
> 
> There's a problem with the way it is currently parsing the KTAP logs on
> IGT. It sounds that it is parsing the data only at the end, and not as
> they arrive. That's bad, as if something goes wrong, the previously
> reported data is still useful.
> 
> Also, when there's a crash, the IGT process is getting segmentation
> fault. So, the end result is that nothing is actually reported.
> 
> 	$ sudo ./build/tests/i915_selftest
> 	IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-990037e9984e+ x86_64)
> 	Segmentation fault (core dumped)

Another issue related to KTAP parsing: this is the output before
the KUnit patch, which is used by IGT CI to check the test results, for
i915 mock selftest:

<snip>
IGT-Version: 1.26-gbab20eb65 (x86_64) (Linux: 6.1.0-rc2-drm-8dacd9299fcc+ x86_64)
process 659 (alsactl) is using audio device. Should be terminated.
Starting subtest: mock
Starting dynamic subtest: sanitycheck
Dynamic subtest sanitycheck: SUCCESS (0.648s)
Starting dynamic subtest: shmem
Dynamic subtest shmem: SUCCESS (0.557s)
Starting dynamic subtest: fence
Dynamic subtest fence: SUCCESS (8.078s)
Starting dynamic subtest: scatterlist
Dynamic subtest scatterlist: SUCCESS (1.531s)
Starting dynamic subtest: syncmap
Dynamic subtest syncmap: SUCCESS (2.875s)
Starting dynamic subtest: uncore
Dynamic subtest uncore: SUCCESS (0.525s)
Starting dynamic subtest: ring
Dynamic subtest ring: SUCCESS (0.529s)
Starting dynamic subtest: engine
Dynamic subtest engine: SUCCESS (0.527s)
Starting dynamic subtest: timelines
Dynamic subtest timelines: SUCCESS (4.177s)
Starting dynamic subtest: requests
Dynamic subtest requests: SUCCESS (3.561s)
Starting dynamic subtest: objects
Dynamic subtest objects: SUCCESS (0.596s)
Starting dynamic subtest: phys
Dynamic subtest phys: SUCCESS (0.602s)
Starting dynamic subtest: dmabuf
Dynamic subtest dmabuf: SUCCESS (0.605s)
Starting dynamic subtest: vma
Dynamic subtest vma: SUCCESS (9.724s)
Starting dynamic subtest: evict
Dynamic subtest evict: SUCCESS (1.660s)
Starting dynamic subtest: gtt
Dynamic subtest gtt: SUCCESS (3.309s)
Starting dynamic subtest: hugepages
Dynamic subtest hugepages: SUCCESS (1.665s)
Starting dynamic subtest: memory_region
Dynamic subtest memory_region: SUCCESS (2.789s)
Subtest mock: SUCCESS (43.961s)
</snip>

This is the logs after your patch:

<snip>
Missing test version string
Executing 18 tests in: i915 mock selftests
kmsg> 1..18
kmsg> i915: i915_mock_sanitycheck() - ok!
kmsg> ok 1 - mock_sanitycheck
kmsg> i915: Running shmem_utils_mock_selftests/igt_shmem_basic
kmsg> ok 2 - mock_shmem
kmsg> i915: Running i915_sw_fence_mock_selftests/test_self
kmsg> i915: Running i915_sw_fence_mock_selftests/test_dag
kmsg> i915: Running i915_sw_fence_mock_selftests/test_AB
kmsg> i915: Running i915_sw_fence_mock_selftests/test_ABC
kmsg> i915: Running i915_sw_fence_mock_selftests/test_AB_C
kmsg> i915: Running i915_sw_fence_mock_selftests/test_C_AB
kmsg> i915: Running i915_sw_fence_mock_selftests/test_chain
kmsg> i915: Running i915_sw_fence_mock_selftests/test_ipc
kmsg> i915: Running i915_sw_fence_mock_selftests/test_timer
kmsg> i915: Running i915_sw_fence_mock_selftests/test_dma_fence
kmsg> Asynchronous wait on fence mock:mock:0 timed out (hint:fence_notify [i915])
kmsg> ok 3 - mock_fence
kmsg> i915: Running scatterlist_mock_selftests/igt_sg_alloc
kmsg> sg_alloc_table timed out
kmsg> i915: Running scatterlist_mock_selftests/igt_sg_trim
kmsg> i915_sg_trim timed out
kmsg> ok 4 - mock_scatterlist
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_init
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_one
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_above
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_join_below
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_neighbours
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_compact
kmsg> i915: Running i915_syncmap_mock_selftests/igt_syncmap_random
kmsg> ok 5 - mock_syncmap
kmsg> ok 6 - mock_uncore
kmsg> i915: Running intel_ring_mock_selftests/igt_ring_direction
kmsg> ok 7 - mock_ring
kmsg> i915: Running intel_engine_cs_mock_selftests/intel_mmio_bases_check
kmsg> ok 8 - mock_engine
kmsg> i915: Running intel_timeline_mock_selftests/mock_hwsp_freelist
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running intel_timeline_mock_selftests/igt_sync
kmsg> i915: Running intel_timeline_mock_selftests/bench_sync
kmsg> bench_sync: 44045 random insertions, 2288ns/insert
kmsg> bench_sync: 44045 random lookups, 80ns/lookup
kmsg> bench_sync: 877617 in-order insertions, 114ns/insert
kmsg> bench_sync: 877617 in-order lookups, 3ns/lookup
kmsg> bench_sync: 6357870 repeated insert/lookups, 10ns/op
kmsg> bench_sync: 19942183 cyclic/1 insert/lookups, 5ns/op
kmsg> bench_sync: 19353937 cyclic/2 insert/lookups, 5ns/op
kmsg> bench_sync: 16969941 cyclic/3 insert/lookups, 5ns/op
kmsg> bench_sync: 14438533 cyclic/5 insert/lookups, 6ns/op
kmsg> bench_sync: 13418112 cyclic/8 insert/lookups, 7ns/op
kmsg> bench_sync: 9257200 cyclic/13 insert/lookups, 10ns/op
kmsg> bench_sync: 53636 cyclic/21 insert/lookups, 1877ns/op
kmsg> ok 9 - mock_timelines
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_request_mock_selftests/igt_add_request
kmsg> i915: Running i915_request_mock_selftests/igt_wait_request
kmsg> i915: Running i915_request_mock_selftests/igt_fence_wait
kmsg> i915: Running i915_request_mock_selftests/igt_request_rewind
kmsg> i915: Running i915_request_mock_selftests/mock_breadcrumbs_smoketest
kmsg> Completed 92 waits for 49042 fence across 8 cpus
kmsg> ok 10 - mock_requests
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_object_mock_selftests/igt_gem_object
kmsg> ok 11 - mock_objects
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_phys_mock_selftests/mock_phys_object
kmsg> ok 12 - mock_phys
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_self
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_import_ownership
kmsg> i915: Running i915_gem_dmabuf_mock_selftests/igt_dmabuf_export_vmap
kmsg> ok 13 - mock_dmabuf
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_create
kmsg> igt_vma_create timed out: after 31 objects in 23 contexts
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_pin1
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_rotate_remap
kmsg> i915: Running i915_vma_mock_selftests/igt_vma_partial
kmsg> ok 14 - mock_vma
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_something
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_for_vma
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_for_cache_color
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_evict_vm
kmsg> i915: Running i915_gem_evict_mock_selftests/igt_overcommit
kmsg> ok 15 - mock_evict
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_drunk
kmsg> drunk_hole timed out after 31635/524288
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_walk
kmsg> walk_hole timed out at 812f000
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_pot
kmsg> pot_hole timed out after 19/33
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_mock_fill
kmsg> fill_hole timed out (npages=1, prime=199)
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_gtt_reserve
kmsg> i915: Running i915_gem_gtt_mock_selftests/igt_gtt_insert
kmsg> ok 16 - mock_gtt
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_exhaust_device_supported_pages
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_memory_region_huge_pages
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_misaligned_dma
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_huge_fill
kmsg> igt_mock_ppgtt_huge_fill timed out at size 43986944
kmsg> i915: Running i915_gem_huge_page_mock_selftests/igt_mock_ppgtt_64K
kmsg> ok 17 - mock_hugepages
kmsg> mock: [drm] Using Transparent Hugepages
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - HuC is not supported!
kmsg> mock: [drm] Incompatible option enable_guc=3 - GuC submission is N/A
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_reserve
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_fill
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_contiguous
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_splintered_region
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_max_segment
kmsg> i915: Running intel_memory_region_mock_selftests/igt_mock_io_size
kmsg> igt_mock_io_size with ps=10000, io_size=10000000, total=cf110000
kmsg> igt_mock_io_size mappable theft=(0MiB/256MiB), total=3313MiB
kmsg> ok 18 - mock_memory_region
kmsg> # i915 mock selftests: pass:18 fail:0 skip:0 total:18
kmsg> # Totals: pass:18 fail:0 skip:0 total:18
kmsg> ok 1 - i915 mock selftests
SUCCESS (29.259s)
</snip>

Basically, the current output will break CI reports presented at:
	https://intel-gfx-ci.01.org/tree/drm-tip/bat-all.html?testfilter=selftest

The IGT output after your change should be similar to what we had
before, e. g. each test should output SUCCESS/FAIL/SKIP (plus the
final result of all tests at the suite).

any other non-KTAP messages from dmesg should be ignored, as, if
needed, those can be obtained later, as IGT runs on bare metal,
and not inside a VM.

Regards,
Mauro