| Summary: | AB-INT PTEST RISCV64: python3 ptest failure (python3-cryptography, python3-more-itertools) | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [QA/Testing] Package Testing (ptest) | Reporter: | João Marcos Costa <joaomarcos.costa> | ||||||
| Component: | ptest | Assignee: | Trevor Gamblin <tgamblin> | ||||||
| Status: | ACCEPTED --- | QA Contact: | |||||||
| Severity: | normal | ||||||||
| Priority: | Medium+ | CC: | mathieu.dubois-briand, randy.macleod, richard.purdie, tim.orling, yoann.congal | ||||||
| Version: | unspecified | ||||||||
| Target Milestone: | 6.1 M4 | ||||||||
| Hardware: | x86 | ||||||||
| OS: | Multiple | ||||||||
| Whiteboard: | AB-INT | ||||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||||
| Verified: | Documentation change: | Don't know | |||||||
| Attachments: |
|
||||||||
|
Description
João Marcos Costa
2026-02-09 09:13:11 UTC
https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1019/steps/13/logs/stdio qemuriscv64-ptest ubuntu2404-vk-2 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1012/steps/14/logs/stdio qemuriscv64-ptest opensuse156-vk-1 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1031/steps/13/logs/stdio qemuriscv64-ptest stream9-vk-1 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1033/steps/13/logs/stdio qemuriscv64-ptest fedora42-vk-1 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1037/steps/13/logs/stdio qemuriscv64-ptest debian12-vk-6 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1039/steps/13/logs/stdio qemuriscv64-ptest fedora42-vk-1 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1053/steps/13/logs/stdio qemuriscv64-ptest stream9-vk-1 Yesterday I built core-image-ptest-python3-cryptography for qemuriscv64 locally, then booted it and set up a loop to run ptest 100 times and collect logs with:
for i in `seq 1 100`; do ptest-runner python3-cryptography 2>&1 | tee logs/cryptography-ptest-$i.log; done
It seems that at least under my emulation conditions, each run takes about 8 minutes (480 seconds) if it passes. I checked the passing run average time with:
grep -rL 'FAIL: [1-9][0-9]*' logs/ | xargs grep -ho 'DURATION: [0-9]*' | sed 's/DURATION: //' | awk '{sum+=$1; n++} END {if (n>0) print "Average:", sum/n; else print "No matches found"}'
The first failure I encountered was on run 63, which means that the runs started failing about 8 hours into running the test loop. This coincides with when my build host would've started kicking off my various nightly maintainer pipelines and thus loaded down the system a lot. In total, 18 runs between #63 and #91 ended up failing:
root@qemuriscv64:~# grep -r 'FAIL: .*[1-9].*' logs/ | sort -u
logs/cryptography-ptest-63.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-64.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-65.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-66.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-67.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-68.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-69.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-70.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-71.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-72.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-73.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-74.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-75.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-76.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-77.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-78.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-79.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-91.log:TOTAL: 1 FAIL: 2
What is notable about the failing runs is that
1) They have a shorter average runtime (339 seconds or a bit over 5.5 minutes)
2) The logs contain output from /usr/bin/ptest-runner-collect-system-data
So it definitely looks like a system loading issue rather than something problematic to the test (although the test is heavy).
Created attachment 5185 [details]
failing ptest log from test looping - some tests run
Created attachment 5186 [details]
failing ptest log from test looping - no tests run
I am setting up a similar test run for qemuarm64, and I'll trigger it at roughly the same time as I did yesterday with qemuriscv64. For now, it's worth noting that the qemuarm64 duration for python3-cryptography's ptests is much lower when the system is not under heavy load: ============================================================================ Testsuite summary # TOTAL: 3547 # PASS: 3381 # SKIP: 166 # XFAIL: 0 # FAIL: 0 # XPASS: 0 # ERROR: 0 DURATION: 315 END: /usr/lib/python3-cryptography/ptest 2026-02-13T15:47 STOP: ptest-runner TOTAL: 1 FAIL: 0 root@qemuarm64:~# qemuriscv64-ptest fedora42-vk-1 master completed at 2026-02-06 04:40:33+00:00 https://valkyrie.yocto.io/pub/non-release/20260206-8/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1045/steps/13/logs/stdio qemuriscv64-ptest opensuse156-vk-1 mathieu/master-next completed at 2026-02-13 17:23:24+00:00 https://valkyrie.yocto.io/pub/non-release/20260213-82/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1075/steps/14/logs/stdio qemuriscv64-ptest fedora42-vk-1 mathieu/master-next completed at 2026-02-14 22:26:18+00:00 https://valkyrie.yocto.io/pub/non-release/20260214-104/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1084/steps/13/logs/stdio Sure enough, I do see some failures for qemuarm64 as well:
root@qemuarm64:~# grep -r 'FAIL: .*[1-9].*' logs/ | sort -u
logs/cryptography-ptest-69.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-71.log:TOTAL: 1 FAIL: 2
logs/cryptography-ptest-74.log:TOTAL: 1 FAIL: 2
Interestingly, the duration numbers seem to be inverted - without any meaningful system load, I saw the ptests on qemuarm64 complete in about ~310 seconds, while in the case of these three failures, they each took ~470 seconds. I did have to delay the start of the loop for the qemuarm64 so that I'd be sure they'd still be running when my system started various builds (and thus be under load).
As for actual failure log content, I see similar results - the tests are running initially, but at the end there's output like:
[ 1.239334] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 1.383230] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:04.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input0
[ 1.384424] hid-generic 0003:0627:0001.0001: input: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:04.0-1/input0
[ 1.426818] udevd[112]: starting version 3.2.14
[ 1.456292] udevd[114]: starting eudev-3.2.14
[ 1.503925] usb 1-2: new high-speed USB device number 3 using xhci_hcd
[ 1.642511] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:04.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/input/input1
[ 1.699561] hid-generic 0003:0627:0001.0002: input: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:04.0-2/input0
[ 1.855308] EXT4-fs (vda): re-mounted 16e4bc89-b90e-4792-9000-d4fd6cd394d5.
init
|-getty 38400 tty1
|-klogd -n
|-sshd
|-start_getty /bin/start_getty 115200 ttyAMA0 vt102
| `-sh
| |-ptest-runner python3-cryptography
| | |-ptest-runner-co /usr/bin/ptest-runner-collect-system-data
| | | `-pstree -a -l
| | `-(run-ptest)
| `-tee logs/cryptography-ptest-71.log
|-syslogd -n -O /var/log/messages
|-ttyrun hvc0 /bin/start_getty 115200 hvc0 vt102
`-udevd -d
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/root 470818 201418 239624 46% /
devtmpfs 2544800 0 2544800 0% /dev
tmpfs 2545728 76 2545652 0% /run
tmpfs 2545728 60 2545668 0% /var/volatile
total used free shared buff/cache available
Mem: 5091456 43572 4885532 4136 162352 4996412
Swap: 0 0 0
ERROR: Exited from signal Killed (9)
DURATION: 466
TIMEOUT: /usr/lib/python3-cryptography/ptest
END: /usr/lib/python3-cryptography/ptest
2026-02-14T02:33
STOP: ptest-runner
TOTAL: 1 FAIL: 2
Just for comparison again, a typical run result on qemuarm64: ============================================================================ Testsuite summary # TOTAL: 3547 # PASS: 3381 # SKIP: 166 # XFAIL: 0 # FAIL: 0 # XPASS: 0 # ERROR: 0 DURATION: 360 END: /usr/lib/python3-cryptography/ptest 2026-02-17T13:17 STOP: ptest-runner TOTAL: 1 FAIL: 0 and one on qemuriscv64: ============================================================================ Testsuite summary # TOTAL: 3547 # PASS: 3381 # SKIP: 166 # XFAIL: 0 # FAIL: 0 # XPASS: 0 # ERROR: 0 DURATION: 500 END: /usr/lib/python3-cryptography/ptest 2026-02-17T13:27 STOP: ptest-runner TOTAL: 1 FAIL: 0 qemuriscv64-ptest rocky9-vk-1 master completed at 2026-02-21 04:01:02+00:00 https://valkyrie.yocto.io/pub/non-release/20260221-8/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1108/steps/13/logs/stdio qemuriscv64-ptest fedora40-vk-2 mathieu/master-next completed at 2026-02-26 10:17:28+00:00 https://valkyrie.yocto.io/pub/non-release/20260226-54/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1132/steps/13/logs/stdio qemuriscv64-ptest rocky9-vk-1 mathieu/master-next completed at 2026-02-24 09:02:09+00:00 https://valkyrie.yocto.io/pub/non-release/20260224-41/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1122/steps/13/logs/stdio qemuriscv64-ptest fedora40-vk-3 master completed at 2026-02-27 10:54:12+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1141/steps/13/logs/stdio Doing a little more testing to confirm variability between architectures. Here's qemuriscv64 over 10 runs:
root@qemuriscv64:~# grep "DURATION:" crypto-ptest-*
crypto-ptest-1.log:DURATION: 496
crypto-ptest-10.log:DURATION: 459
crypto-ptest-2.log:DURATION: 467
crypto-ptest-3.log:DURATION: 477
crypto-ptest-4.log:DURATION: 463
crypto-ptest-5.log:DURATION: 476
crypto-ptest-6.log:DURATION: 457
crypto-ptest-7.log:DURATION: 458
crypto-ptest-8.log:DURATION: 459
crypto-ptest-9.log:DURATION: 462
root@qemuriscv64:~# grep -ho 'DURATION: [0-9]*' crypto-ptest-* | sed 's/DURATION: //' | awk '{sum+=$1; n++} END {if (n>0) print "Average:", sum/n; else print "No matches found"}'
Average: 467.4
root@qemuriscv64:~#
versus qemuarm64:
root@qemuarm64:~# grep "DURATION:" crypto-ptest-*
crypto-ptest-1.log:DURATION: 321
crypto-ptest-10.log:DURATION: 301
crypto-ptest-2.log:DURATION: 305
crypto-ptest-3.log:DURATION: 307
crypto-ptest-4.log:DURATION: 304
crypto-ptest-5.log:DURATION: 301
crypto-ptest-6.log:DURATION: 307
crypto-ptest-7.log:DURATION: 301
crypto-ptest-8.log:DURATION: 313
crypto-ptest-9.log:DURATION: 304
root@qemuarm64:~# grep -ho 'DURATION: [0-9]*' crypto-ptest-* | sed 's/DURATION: //' | awk '{sum+=$1; n++} END {if (n>0) print "Average:", sum/n; else print "No matches found"}'
Average: 306.4
root@qemuarm64:~#
qemuriscv64-ptest rocky9-vk-1 mathieu/master-next completed at 2026-03-05 13:20:33+00:00 https://valkyrie.yocto.io/pub/non-release/20260305-75/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1176/steps/13/logs/stdio I spent some time trying to collect some logs around QEMU behaviour between qemuriscv64 and qemuarm64. I've run the following runqemu calls for both: 1. runqemu nographic snapshot qemuparams="-D arm64_helpers.log -d out_asm" 2. runqemu nographic snapshot qemuparams="-D arm64_traps.log -d int,guest_errors" 3. runqemu nographic snapshot qemuparams="-D arm64_unimp.log -d unimp,guest_errors" The log files are huge, so it's not easy to share the data without further processing, so I'll work on that. Here are some interesting highlights. The helpers output is a little less than 50% higher for riscv64 than arm64 (and I'm trying not to read too much into the fact that this discrepancy aligns with the cryptography ptest runtimes, yet...): tgamblin@megalith ~/workspace/yocto/openembedded-core/build/qemu_profiling (master)$ ls -l total 1967724 -rw-r--r--. 1 tgamblin tgamblin 317759652 Mar 6 13:46 arm64_helpers.log -rw-r--r--. 1 tgamblin tgamblin 796497115 Mar 6 13:40 arm64_traps.log -rw-r--r--. 1 tgamblin tgamblin 0 Mar 6 13:29 arm64_unimp.log -rw-r--r--. 1 tgamblin tgamblin 447980602 Mar 6 12:33 riscv64_helpers.log -rw-r--r--. 1 tgamblin tgamblin 452694492 Mar 6 12:34 riscv64_traps.log -rw-r--r--. 1 tgamblin tgamblin 1093 Mar 6 13:28 riscv64_unimp.log Also worth noting there that the traps' file sizes are inverted - arm64 is much larger. As for the unimplemented check, the logs are short (nothing in arm64!). Here's the entirety of what's in the riscv64 log: ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds QEMU does not support mixed HSXLEN options.ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds QEMU does not support mixed HSXLEN options.CSR_STVEC: reserved mode not supported ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds QEMU does not support mixed HSXLEN options.CSR_STVEC: reserved mode not supported ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds ignoring pmpaddr read - out of bounds ignoring pmpaddr write - out of bounds QEMU does not support mixed HSXLEN options.CSR_STVEC: reserved mode not supported virtio_mmio_write: attempt to write guest features with guest_features_sel > 0 in legacy mode virtio_mmio_write: attempt to write guest features with guest_features_sel > 0 in legacy mode pmp is RISC-V Physical Memory Protection, an extension which is part of the privileged ISA. The "ignoring pmpaddr" messages are in target/riscv/pmp.c, in pmpaddr_csr_write() and pmpaddr_csr_read() respectively. The HSXLEN message comes from write_hstatus() in target/riscv/csr.c. The virtio_mmio_write() one is in the VIRTIO_MMIO_DRIVER_FEATURES case of a big switch block. Still digging. There's a lot of data to process and RP has pointed out a possible issue with buffer size variance between architectures, so I'm going to look there too. Worth noting too that some of the output in the previous comment will be "normal" messages that are seen during boot as enumeration happens and some options fallback to different modes, etc. qemuriscv64-ptest fedora39-vk-1 mathieu/master-next completed at 2026-03-06 15:19:30+00:00 https://valkyrie.yocto.io/pub/non-release/20260306-90/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1187/steps/13/logs/stdio qemuriscv64-ptest rocky9-vk-1 master completed at 2026-03-07 03:31:43+00:00 https://valkyrie.yocto.io/pub/non-release/20260307-11/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1189/steps/13/logs/stdio qemuriscv64-ptest debian11-vk-1 master completed at 2026-03-09 02:40:52+00:00 https://valkyrie.yocto.io/pub/non-release/20260309-8/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1204/steps/13/logs/stdio Fixed by: https://git.openembedded.org/openembedded-core/commit/?id=869d70d46c8e31cfc380b5143059cab3713cae26 qemuriscv64-ptest debian12-vk-5 mathieu/master-next completed at 2026-07-16 15:53:58+00:00 https://valkyrie.yocto.io/pub/non-release/20260716-82/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/1929/steps/13/logs/stdio qemuriscv64-ptest debian12-vk-7 mathieu/master-next completed at 2026-07-29 08:01:04+00:00 https://valkyrie.yocto.io/pub/non-release/20260729-34/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2018/steps/13/logs/stdio qemuriscv64-ptest opensuse156-vk-1 wrynose completed at 2026-07-30 15:37:48+00:00 https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2032 qemuriscv64-ptest alma8-vk-1 mathieu/master-next completed at 2026-09-02 17:01:23+00:00 https://valkyrie.yocto.io/pub/non-release/20260902-80/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2311/steps/16/logs/stdio Another timeout, in python3-more-itertools: https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2324/steps/15/logs/stdio qemuriscv64-ptest debian12-vk-3 Reopening. https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2363/steps/16/logs/stdio qemuriscv64-ptest opensuse156-vk-1 Trevor to look, maybe create a separate bug as needed. I have opened this bug for python3-more-itertools failures: https://bugzilla.yoctoproject.org/show_bug.cgi?id=16422 qemuriscv64-ptest opensuse160-vk-1 mathieu/master-next completed at 2026-10-06 08:06:25+00:00 https://valkyrie.yocto.io/pub/non-release/20261006-35/testresults/qemuriscv64-ptest/ https://autobuilder.yoctoproject.org/valkyrie/#/builders/56/builds/2556/steps/15/logs/stdio |