We have discovered a new instance of 11898, timeout error for the bitbake server. We only see it on fact machines, and it can be either always hit or rarely hit. This kills Toaster on fast (e.g. Continuous Integration) machines, but also reveals a lurking vulnerability for all bitbake users. The best way to replicate the error is to do "server.runCommand(["getVariable", "TMPDIR"])[0]" several times in a row in a popular event handler in the UI of choice. One call is either enough or up to a hunderd calls is needed. We found it trying to run Toaster on a very fast machine. I am creating the knotty replicator now.
Created attachment 4021 [details] knotty_12116.py : server timeout replicator Attached is "knotty_12116.py", a simple version of knotty that can replicate the server crash. Here are replication steps: $ . ./oe-init-build-env $ rm -rf cache tmp/ sstate-cache/ downloads/ buildhistory/ $ bitbake -u knotty_12116 core-image-minimal ... vvv BEFORE SERVER.RUNCOMMAND() vvv Timeout while waiting for a reply from the bitbake server $ Notes: 1) You will observe that I added the following section to several of the high frequency event handlers, specifically 'bb.event.ParseProgress', 'bb.event.CacheLoadProgress', and 'bb.build.TaskProgress'. if isinstance(event, bb.event.ParseProgress): ### TRY TO GET VALUE FROM BB SERVER ### print("vvv BEFORE SERVER.RUNCOMMAND() vvv") tmp_dir = server.runCommand(["getVariable", "TMPDIR"])[0] tmp_dir = server.runCommand(["getVariable", "TMPDIR"])[0] tmp_dir = server.runCommand(["getVariable", "TMPDIR"])[0] tmp_dir = server.runCommand(["getVariable", "TMPDIR"])[0] print("^^^ AFTER SERVER.RUNCOMMAND() ^^^") 2) I needed the 'core-image-minimal' target. I did not hit it with for example "quilt-native'. I have never hit on my slower host after #11898 was fixed. 3) You will need the "rm -rf" command, else your build will start after the critical sections and not fault. 4) I will underline again that this is a lot harder to hit than the original issue found in #11898. 5) I you have a hard time replicating it on your (presumably slower) hosts, let us know how we can instrument our bitbake to get you data.
Hi David, In lib/bb/server/process.py there is a line, "self.recv.poll(5)". Could you test increasing 5 to something higher like 30 and see if that avoids the issues you've been seeing please? I have been able to reproduce but only vary rarely, say once every 30 minutes of a build... Cheers, Richard
Changing the poll timeout to 30 helps. I alternated from 5 to 30 and I got the timeout twice with a timeout of 5 and the build started twice when the timeout was set to 30.
(In reply to comment #3) > Changing the poll timeout to 30 helps. I alternated from 5 to 30 and I got > the timeout twice with a timeout of 5 and the build started twice when the > timeout was set to 30. I'm suspecting this is the real fix, the code just isn't waiting long enough for a reply from the server and under real world loads, a timeout of 5s is possible. A timeout of 30s would be particularly bad...
Bumping the timeout to 30 seconds (ugh!) is a workaround and a reasonable one for 2.4. It seems that the two double-digit timeouts in lib/bb/server/process.py are now both 30 seconds so that's a bonus! :) I've opened an enhancement for 2.5: run build tasks at lower priority than bitbake UI and server https://bugzilla.yoctoproject.org/show_bug.cgi?id=12117 Also, in a few weeks, we could spend more time analyzing the scheduling behaviour on the systems where we see this problem to understand why the timeout is being hit. I suspect that with equal priority/niceness and 100s or 1000s of tasks, and perhaps a slow, non-empty disk, that 5 seconds is just too short.
I will add that with this patch my reproducer also does not fail anymore. I may file an enhancement request to trigger an event if there should be a timeout, because currently when it happens the build instantly fails but the UI (specifically Toaster) is not informed of that fact and progress appears to hang for the user. I expect that there are other fatal errors that do not have events, but this is the only one I have hit in the last year or so. I may also add code in Toaster to periodically test for such zombie builds, but that may lead into a nest of other issues.
(In reply to comment #6) > I will add that with this patch my reproducer also does not fail anymore. > > I may file an enhancement request to trigger an event if there should be a > timeout, because currently when it happens the build instantly fails but the > UI (specifically Toaster) is not informed of that fact and progress appears > to hang for the user. > > I expect that there are other fatal errors that do not have events, but this > is the only one I have hit in the last year or so. > > I may also add code in Toaster to periodically test for such zombie builds, > but that may lead into a nest of other issues. The issue here is that the UI can't talk to the server. It tries, the server is busy (likely running something which takes longer like an event handler) and therefore doesn't respond in a time the UI is happy with. You can't trigger an event in this context since there is no server to actually submit it to. 5s was too short for this, 30s is reasonable. The timeout was short due to other UI interaction issues but those were resolved separately so this can be bumped up.
http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=7a822506c0ae402f65c306ce10c05e195138c464
Created attachment 4044 [details] knotty_server_histogram.py: server call histograms
To follow up I modified a version of knotty (attached) that included s histogram of inserted server call latencies, in hopes to show where we were with regards to 5 verses 30 seconds timeout setting. To do this test I did 5 server calls for every event that knotty received, and to really test it I grabbed the larger event list that Toaster uses. I then ran it on the machine where we were able to replicate the server timeouts and did a "core-image-minimal" from scratch. This is what I found. Server latency in seconds: Seconds Count 0 6693 1 0 2 0 3 0 4 1 5 1 6 0 7 0 ... 0 Out of 6,691 aggressive calls across the build, only two were longer than one second, and even those just barely touched the 5 second mark. My conclusion is that the problem was indeed solved, and that the few outliers are just that. Here are replication steps: $ . ./oe-init-build-env $ rm -rf cache tmp/ sstate-cache/ downloads/ buildhistory/ $ bitbake -u knotty_server_histogram core-image-minimal $ cat /tmp/bb_server_histogram.csv
One more comment. I changed the threshold in the attached script to capture all events longer than 3 seconds as opposed to 5 seconds. If you do that you see the follow entries. Server high latency events: Event# Loop Latency Event 155 2 4 <bb.event.RecipeParsed object at 0x7f5ea2265d68> 155 3 5 <bb.event.RecipeParsed object at 0x7f5ea2265d68> The delays occur early in the Recipe Parsing phase, and is quite visible in the knotty's shell progress bar. This is consistent with the failures being observed early in the build (before the patch was applied). Each server call is done 5 times in a fast loop, and the above "Loop" value is the iteration. The loop number appear random in my several runs (as opposed to always being the first call), telling me that it is one of the background parsing tasks that the server call happens to overlap with.