Bug 13950 - Intermittent qemu connection failures during oe-selftest on autobuilder
Summary: Intermittent qemu connection failures during oe-selftest on autobuilder
Status: RESOLVED OBSOLETE
Alias: None
Product: OE-Core
Classification: Build System, Metadata & Runtime
Component: core (show other bugs)
Version: 3.1
Hardware: x86 Multiple
: Medium+ normal
Target Milestone: 3.4 M3
Assignee: Sakib Sajal
QA Contact:
URL:
Whiteboard: AB-INT
Depends on:
Blocks:
 
Reported: 2020-06-18 08:57 UTC by Steve Sakoman
Modified: 2021-07-12 19:31 UTC (History)
6 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: ---
Verified:
Documentation change: No (bug/feature does not impact docs)


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Steve Sakoman 2020-06-18 08:57:02 UTC
Seen on oe-selftest-ubuntu and oe-selftest-centos so not distro specific

Error messages are either:

step2d: ERROR: core-image-minimal-1.0-r0 do_testimage: Qemu pid didn't appear in 120 seconds

or:
step2d: ERROR: core-image-minimal-1.0-r0 do_testimage: Didn't receive a console connection from qemu.

Recent examples:

https://autobuilder.yoctoproject.org/typhoon/#/builders/87/builds/1031
https://autobuilder.yoctoproject.org/typhoon/#/builders/87/builds/1032
https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1041
https://autobuilder.yoctoproject.org/typhoon/#/builders/87/builds/1027
https://autobuilder.yoctoproject.org/typhoon/#/builders/87/builds/1028
Comment 1 Randy MacLeod 2020-06-25 07:35:43 UTC
Seems to be dunfell specific according to Richard. Could be a stuck tap device.
Comment 2 Richard Purdie 2020-07-09 07:26:24 UTC
Had a spate of these in https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1120
Comment 3 Randy MacLeod 2020-07-09 08:11:00 UTC
Sakib, please get started with this one this week and once you have a handle on it, we can brainstorm how to proceed.
Comment 4 Richard Purdie 2020-07-13 04:55:16 UTC
The logs are odd as it shouldn't happen, qemu *is* running, oeqa code just isn't seeing it.

I added http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=71772fbaea840da03835782b8602613895cf02ce for extra debug and http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=0c1c6c971de40ec3c9094a3963e5b6cc063b0e64 as a potential fix (although I couldn't spot any chdir). If/when the issue does reoccur we may at least be able to get more information.
Comment 5 Richard Purdie 2020-07-16 07:03:52 UTC
Still seeing the failures, master-next, included the new debug output:
https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1159

Good and bad, we now have more data, the problem definitely isn't fixed.
Comment 6 Richard Purdie 2020-07-16 11:32:57 UTC
That logs shows full pathnames to the pid file being specified, The pid file is never created and the ps output shows the qemu process is running. It seems odd that it wouldn't write the file after 2 minutes.

I was thinking these processes had priority as we set:

BB_TASK_NICE_LEVEL = '5'
BB_TASK_NICE_LEVEL_task-testimage = '0'
BB_TASK_IONICE_LEVEL = '2.7'
BB_TASK_IONICE_LEVEL_task-testimage = '2.1'

however qemu run outside of testimage tasks doesn't get this benefit. Perhaps we should look at addressing that for runqemu launched processes? Unfortunately due to the way nice levels work, you need to drop nice level in the places you don't want it rather than being able to raise it in critical sections and I think you can only lower, not raise so the core scheduling process has to have the higher level.
Comment 7 Richard Purdie 2020-07-16 11:59:58 UTC
To get an idea of the system load, I tried to write out what it was running in parallel when this failed:
a) compiling cairo
b) core-image-sato-dev do_image_wic
c) core2-32 gobject-introspection compile (running g-ir-scanner)
d) qemuarm64 running under qemu for core-image-sato-sdk
e) qemuarm-alt running under qemu for core-image-lsb-sdk
f) meta-intel target gcc do_compile
g) core2-32 gettext do_configure
h) meta-intel tcl do_install_ptest
i) meta-intel grub-efi do_compile
j) meta-intel boost do_compile
k) perl boost do_install_ptest
l) selftest devtool modify virtual/kernel
m) selftest wic image creation
n) qemux86-64 core-image-sato-sdk image build

(plus probably other selftest bits). That is a fairly heavy workload :/.
Comment 8 Richard Purdie 2020-07-21 05:38:09 UTC
https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1177 is a failure with much lower system load. It has prioirity/nice info showing that most of the builds are "nice 5" but qemu is "nice 0" meaning it should have priority.
Comment 9 Richard Purdie 2020-07-21 15:48:05 UTC
Had a nice theory about the pidfile name being the issue and added a patch in master-next to avoid that potential issue. Failures still occur so its not that:
https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1178
Comment 10 Richard Purdie 2020-07-22 07:04:14 UTC
Further notes:

On my local build server
sudo sh -c "echo 3 > /proc/sys/vm/drop_caches" then run qemu, pid takes 1.6s to appear

qemu-system-x86_64 <options> -enable-kvm -snapshot -pidfile /media/build1/poky/rptest & while true; do date +%S:%N; cat /media/build1/poky/rptest; if [ "$?" == "0" ]; then break; fi; done;

dd if=/dev/zero of=loadfile bs=1M count=1024; while true; do cp loadfile loadfile1; done on the other terminal makes it take 4.4s

Comparing logs with our dropcaches on the autobuilder:

failure log:
DEBUG: waiting at most 120 seconds for qemu pid (07/21/20 22:16:14)
ERROR: Qemu pid didn't appear in 120 seconds (07/21/20 22:18:19)
dmesg:
[Tue Jul 21 16:00:57 2020] dropcache (24724): drop_caches: 3
[Wed Jul 22 00:02:18 2020] dropcache (12281): drop_caches: 3

so no correlation.
Comment 11 Richard Purdie 2020-07-22 14:38:20 UTC
Theory #4, the nice level of the janitor cleanup process needs to be set higher. We're now testing with http://git.yoctoproject.org/cgit.cgi/yocto-autobuilder-helper/commit/?id=29a1c23b292b4e762f01c4c707aee6ea39e0589f applied since both recent traces had janitor rm activity shown in the ps traces. Would be good to go through the previous failures and see if this is a pattern.
Comment 12 Richard Purdie 2020-07-25 07:13:45 UTC
Hate to say it but I think https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1188 means this is still an issue (was a dunfell build, rm from janitor was nice/ionice but the devtool deletion from selftest was not so maybe that was the issue here?)
Comment 13 Steve Sakoman 2020-08-04 07:25:27 UTC
Another occurrence on a dunfell build: https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1214
Comment 14 Randy MacLeod 2021-05-13 15:05:54 UTC
There are more specific bugs to cover this issue.