On Thu, 3 Nov 2022 10:48:40 +0100 Mauro Carvalho Chehab <mauro.chehab@xxxxxxxxxxxxxxx> wrote: > On Sun, 28 Aug 2022 21:09:19 -0300 > Isabella Basso <isabbasso@xxxxxxxxxx> 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@xxxxxxxxxx> > > 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
