Bug 8141

Created attachment 2653 [details]
results of nightly-qa-systemd build 423

Created attachment 2654 [details]
results of nightly-qa-systemd build 417

Since this happens during boot before the tests even run, the next step would probably be trying to reproduce this outside of the test scenario.

For example, try boot looping a failed image using runqemu and see how long it takes to fail. It may also be of value to try it with kvm enable just to get the reboot cycle to be that much faster(assuming that doesn't prevent it from reproducing).

As Brian mentioned it might also be useful to make the patch at https://git.yoctoproject.org/cgit/cgit.cgi/poky-contrib/commit/?h=rewitt/systemd_debug&id=cf8a6044c5710aaaadeeb56720d3f905503beb12 output repeatedly(like every 15 seconds) to see if ttyS0 actually disappears.

I tried to reproduce without success,

Some interesting facts is that only success one time [1] and it was in master-next branch.

[1] http://errors.yoctoproject.org/Errors/Search/?query=Dependency+failed+for+Serial+Getty

This seems to be (In reply to comment #4)
> I tried to reproduce without success,
> 
> Some interesting facts is that only success one time [1] and it was in
> master-next branch.
> 
> [1]
> http://errors.yoctoproject.org/Errors/Search/
> ?query=Dependency+failed+for+Serial+Getty

This seems to be related to specific commit in master-next,

005a5b60f00a898b701de6df7095adf7440acebf

Created attachment 2667 [details]
AB log

It happened again in a MUT build, attaching the log from the autobuilder with the improved reporting.

This failures seems to be related to devices I/O blocking the TCG in qemu.

I was able to reproduce emulating load i/o condition (usleep(300)) in qemu code see attachment. This don't happen in kvm because kvm isn't blocked by devices I/O.

I propose the next changes for address this kind of issues,

- KVM enable on x86 and x86-64 machines.
- Run sanity tests when builds aren't running.

For a quick solution may be not the best we can try to reduce the simultaneous builds on AB's.

Created attachment 2672 [details]
qemu usleep hack

Created attachment 2677 [details]
Use g_poll instead of ppoll

I found that if we change the default qemu method from ppoll to g_poll it didn't fail.

For have this scenario you need to apply usleep patch and this one.

Created attachment 2694 [details]
systemd device timeout increase

Using the usleep patch for emulating I/O load. I found that systemd uses a default timeout for devices (90 secs), i increased to 240secs the timeout and works the tty devices took ~195 secs to start.

http://lists.openembedded.org/pipermail/openembedded-core/2015-August/109616.html

Merged at,

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/?id=ea3384e9f84388d60331ba24f67ce5716ce45ee0

(In reply to comment #12)
> Merged at,
> 
> http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/
> ?id=ea3384e9f84388d60331ba24f67ce5716ce45ee0

I made a mistake the correct url is,

http://git.yoctoproject.org/cgit/cgit.cgi/poky/commit/meta/recipes-core/systemd?id=995b6d68df28dbe5770a2202de003d2516690e13

Looks like https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/473/steps/Running%20Sanity%20Tests/logs/stdio included the timeout increase and still failed to start ttyS0 (timing out after four minutes).  I'm not sure "increase the timeout to ten minutes" would be a good fix.

I'm afraid I'm not convinced we've got to the bottom of this...

(In reply to comment #14)
> Looks like
> https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/
> 473/steps/Running%20Sanity%20Tests/logs/stdio included the timeout increase
> and still failed to start ttyS0 (timing out after four minutes).  I'm not
> sure "increase the timeout to ten minutes" would be a good fix.

I know that isn't the best fix but if QEMU is getting more slow and systemd handle dependencies (getty over tty) in this manner we don't have too much to do.

I modified the getty unit to remove the dependency and it works (only remains after rules) that will be another way to solve it. What you think?

(In reply to comment #16)
> (In reply to comment #14)
> > Looks like
> > https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/
> > 473/steps/Running%20Sanity%20Tests/logs/stdio included the timeout increase
> > and still failed to start ttyS0 (timing out after four minutes).  I'm not
> > sure "increase the timeout to ten minutes" would be a good fix.
> 
> I know that isn't the best fix but if QEMU is getting more slow and systemd
> handle dependencies (getty over tty) in this manner we don't have too much
> to do.
> 
> I modified the getty unit to remove the dependency and it works (only
> remains after rules) that will be another way to solve it. What you think?

Also the systemd/avahi issue seems to be the same cause it fails due to timeout.

https://bugzilla.yoctoproject.org/show_bug.cgi?id=8142

I *think* I have a solution to this.
----
the short form:
on the ab run the bitbake build and oeselftest step as ionice -c3, but run the qemu sanity tests w/o nice or ionice.
-----
the longer form:
I used rewitts container testing solution to do these tests in bulk. I found the following:

In the case where I provided a heavy io load (3 simultaneously running bitbake core-image-sato from sstate in a loop) I had on the order of 30-40% failures due to systemd timeout/failure issues.

In the case where I ran the io loaders (again 3 simultaneously running bitbake core-image-sato from sstate in a loop) under ionice -c3. I still have load averages of 35-40 but I now have 0 systemd failures in 425 runs. 

The ionice -c3 tells the builders to only use io under idle meaning that it only gets disk access if no other process has asked for io in a "defined grace period" aka 250 ms.

The bitbake builders are not stalled or starved out since the sanity tests are not doing heavy io but they do need io when they ask for it.

This does require /sys/block/<device>/queue/scheduler to be cfq.  Mine looks like:
noop deadline [cfq] on ubuntu 14.04. Default was [deadline] which makes ionice do nothing. centos6 has [cfq] set on the ab, ubuntu1204 doe not; it has [deadline].

If you have a raid set up it will show the scheduler as none, since you need to set the scheduler on the block device itself.

In which case I have a question. Does the priority level also help in that case?

Could we do something like:

diff --git a/bitbake/lib/bb/build.py b/bitbake/lib/bb/build.py
index 948c395..4a25acf 100644
--- a/bitbake/lib/bb/build.py
+++ b/bitbake/lib/bb/build.py
@@ -414,6 +414,10 @@ def _exec_task(fn, task, d, quieterr):
         newnice = os.nice(nice)
         logger.debug(1, "Renice to %s " % newnice)
 
+    import psutil
+    p = psutil.Process(os.getpid())
+    p.set_ionice(psutil.IOPRIO_CLASS_BE, 7)
+
     bb.utils.mkdirhier(tempdir)
 
     # Determine the logfile to generate

(see the conditional code just above this patch which handles nice level) Our autobuilder does:

BB_TASK_NICE_LEVEL = "5"
BB_TASK_NICE_LEVEL_task-testimage = "0"

and I'm wondering if we can do something similar for ionice? We have to change the default since you can only lower your priority as non-root, not raise it iirc. It would be good to see if we can make this work as best-effort instead of dropping to idle if we can.

I also worry about depending on psutil, but one step at a time.

We added ioprio code to bitbake:

http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=290534d3ff53b3c0a50e480863474d1785088c5a

and enabled it in the autobuilder: 

http://git.yoctoproject.org/cgit.cgi/yocto-autobuilder/commit/?id=2f18ff6807f90543773602554da52083f3f64d0a

In many repeated tests (thousands), this change resolved the issues see here. If we see this again we can reconsider.

As of nightly-qa-systemd Build #600 dd0ba9ea4a11ab15348d4fe3574e4b28784db82f this issue seems to be fixed long time ago.