Bug 15651

Summary:	strace ptest shows multiple levels of breakage
Product:	[QA/Testing] Package Testing (ptest)	Reporter:	Richard Purdie <richard.purdie>
Component:	ptest	Assignee:	Randy MacLeod <randy.macleod>
Status:	NEW ---	QA Contact:
Severity:	normal
Priority:	Medium+	CC:	randy.macleod
Version:	unspecified
Target Milestone:	6.1 M1
Hardware:	x86
OS:	Multiple
Whiteboard:
OS type for building Yocto:	---	Type of Regression:	---
Verified:		Documentation change:	No (bug/feature does not impact docs)

Description Richard Purdie 2024-11-19 15:12:32 UTC

https://valkyrie.yoctoproject.org/#/builders/73/builds/401

The build is hanging.

Looking at the testimage task log, it is 6GB in size. The reason why is the tar output collection is being printed into the log as binary data:

https://valkyrie.yocto.io/pub/shared-failure-data/log.do_testimage.2400954

So firstly we need to fix that.

Secondly a test fails:

https://valkyrie.yocto.io/pub/shared-failure-data/ptest-runner.log

and finally, there is a lot of noise in dmesg from the test run including an OOM:

https://valkyrie.yocto.io/pub/shared-failure-data/qemu_boot_log.20241118102253

not sure if the OOM is related to the test failure or not.

There is the question of why the task finished but cooker is still running too.

Comment 1 Richard Purdie 2024-11-19 15:15:07 UTC

bitbake-cookerdaemon shows nothing interesting, pings are succeeding. The console output shows the core-image-ptest-strace did finish and the log output is shown but somehow bitbake never marked the task as completed.

Comment 2 Richard Purdie 2024-11-19 15:17:35 UTC

Nothing significant in the host dmesg.

Comment 3 Richard Purdie 2024-11-19 15:27:51 UTC

bitbake-worker is looping in worker_flush writing 64kb at a time:

mmap(NULL, 2218389504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d93c00000
munmap(0x712c8b400000, 2218455040)      = 0
futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xb47bd8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1)  = 0
pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997040})
write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218387790) = 65536
mmap(NULL, 2218323968, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d0f800000
munmap(0x712d93c00000, 2218389504)      = 0
futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1)  = 0
pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996730})
write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218322254) = 65536
mmap(NULL, 2218258432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712c8b400000
munmap(0x712d0f800000, 2218323968)      = 0
futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1)  = 1
futex(0xb47b80, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=673516, tv_nsec=134260404}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1)  = 0
pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996940})
write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218256718) = 65536
mmap(NULL, 2218192896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d93c00000

(gdb) py-bt
Traceback (most recent call first):
  File "/srv/pokybuild/yocto-worker/qemux86-64-ptest/build/bitbake/bin/bitbake-worker", line 108, in worker_flush
    worker_queue_int = worker_queue_int[written:]
  File "/usr/lib/python3.12/threading.py", line 1010, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap
    self._bootstrap_inner()

Comment 4 Richard Purdie 2024-11-19 15:59:53 UTC

The delay is around the mmap, which corresponds to:

                worker_queue_int = worker_queue_int[written:]

in the worker code.

Comment 5 Richard Purdie 2024-11-19 16:01:20 UTC

With timestamps:

17:00:53.877740 munmap(0x712d9aa00000, 2101735424) = 0
17:00:54.056454 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1
17:00:54.056501 futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
17:00:54.056618 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0
17:00:54.056650 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997460})
17:00:54.056734 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101668174) = 65536
17:00:54.056850 mmap(NULL, 2101604352, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d9aa00000
17:00:55.085339 munmap(0x712d1d400000, 2101669888) = 0
17:00:55.263597 futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1) = 1
17:00:55.263668 futex(0xb47bd8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
17:00:55.263727 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0
17:00:55.263787 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997420})
17:00:55.263887 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101602638) = 65536
17:00:55.264014 mmap(NULL, 2101538816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d1d400000
17:00:56.283010 munmap(0x712d9aa00000, 2101604352) = 0
17:00:56.461363 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1
17:00:56.461436 futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
17:00:56.461495 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0
17:00:56.461555 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996780})
17:00:56.461656 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101537102) = 65536
17:00:56.461736 mmap(NULL, 2101473280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d9aa00000
17:00:57.500454 munmap(0x712d1d400000, 2101538816) = 0
17:00:57.677700 futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1) = 1
17:00:57.677770 futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 1
17:00:57.677826 futex(0xb47b84, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=675735, tv_nsec=3601111}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
17:00:57.677904 futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 0
17:00:57.677962 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997310}

Comment 6 Richard Purdie 2024-11-20 15:13:49 UTC

For the record, strace ptest creates a 43GB sparse file which is why the data transfer is huge when saving artefact data.

Comment 7 Richard Purdie 2024-11-20 22:20:04 UTC

Summary of issues found: https://lists.openembedded.org/g/openembedded-core/message/207476

Comment 8 Randy MacLeod 2024-11-21 15:37:24 UTC

For the strace issue which is all that remains thanks to Richard.