Profiling takes a long time on veriton

[Max Brustkern]

On the acer veriton machines we use for bootspeed in the ci lab, profiling is taking in excess of 30 minutes. I'm attaching the ureadahead log and the fstab.

[Steve Langasek (vorlon)]

Hi Max,

Note that the ureadahead job is 'stop on stopped rc'. So if it's still running after 30 minutes, that seems to mean that the rc job hasn't completed, so the system is stuck still "booting". Can you show the output of 'initctl --system list' on this system?

[Max Brustkern (nuclearbob)]

I'll get the machine back into that state and get that output.

[Max Brustkern (nuclearbob)]

Here's the status shortly after boot. I'll get another dump once some time has passed:
avahi-cups-reload stop/waiting
avahi-daemon start/running, process 743
mountall-net stop/waiting
mountnfs-bootclean.sh start/running
passwd stop/waiting
rc start/running, process 822
rsyslog start/running, process 510
startpar-bridge stop/waiting
tty4 start/running, process 823
udev start/running, process 284
upstart-udev-bridge start/running, process 277
ureadahead-other stop/waiting
whoopsie start/running, process 989
apport start/running
console-setup stop/waiting
hwclock-save stop/waiting
irqbalance stop/waiting
plymouth-log stop/waiting
systemd-logind start/running, process 662
tty5 start/running, process 827
failsafe stop/waiting
hybrid-gfx stop/waiting
modemmanager start/running, process 635
mountall.sh start/running
rfkill-store stop/waiting
dbus start/running, process 597
failsafe-x stop/waiting
mounted-var stop/waiting
plymouth-shutdown stop/waiting
plymouth stop/waiting
resolvconf start/running
ssh start/running, process 870
udev-fallback-graphics stop/waiting
checkroot.sh start/running
control-alt-delete stop/waiting
hwclock stop/waiting
mounted-proc stop/waiting
network-manager start/running, process 818
alsa-store stop/waiting
cups-browsed start/running, process 874
setvtrgb stop/waiting
shutdown stop/waiting
alsa-restore stop/waiting
cron start/running, process 895
lightdm start/running, process 906
mountall stop/waiting
mounted-debugfs stop/waiting
mountkernfs.sh start/running
console stop/waiting
mounted-run stop/waiting
acpid start/running, process 884
bluetooth start/running, process 673
checkfs.sh start/running
checkroot-bootclean.sh start/running
kmod stop/waiting
mountnfs.sh start/running
plymouth-stop stop/waiting
rcS stop/waiting
ufw start/running
wait-for-state stop/waiting
bootmisc.sh start/running
flush-early-job-log stop/waiting
friendly-recovery stop/waiting
rc-sysinit stop/waiting
cups start/running, process 770
pulseaudio stop/waiting
upstart-socket-bridge start/running, process 523
anacron start/running, process 882
mountdevsubfs.sh start/running
tty2 start/running, process 835
udevtrigger stop/waiting
upstart-file-bridge start/running, process 480
container-detect stop/waiting
mounted-dev stop/waiting
mtab.sh start/running
tty3 start/running, process 836
udev-finish stop/waiting
alsa-state stop/waiting
hostname stop/waiting
mountall-reboot stop/waiting
mountall-shell stop/waiting
mounted-tmp stop/waiting
network-interface (lo) start/running
network-interface (eth0) start/running
network-interface (wlan1) start/running
network-interface (wlan0) start/running
plymouth-ready stop/waiting
plymouth-splash stop/waiting
plymouth-upstart-bridge stop/waiting
tty1 stop/waiting
udevmonitor stop/waiting
dmesg stop/waiting
mountall-bootclean.sh start/running
network-interface-security (network-manager) start/running
network-interface-security (network-interface/eth0) start/running
network-interface-security (network-interface/wlan0) start/running
network-interface-security (network-interface/wlan1) start/running
network-interface-security (network-interface/lo) start/running
network-interface-security (networking) start/running
networki...

[Max Brustkern (nuclearbob)]

11 minutes later there are no changes in the output.

[Steve Langasek (vorlon)]

On Fri, Feb 21, 2014 at 09:29:04PM -0000, Max Brustkern wrote:
> rc start/running, process 822

ok, so the 'rc' job is indeed still running. Can you show pstree (or
equivalent) output so we can see what's going on with the subprocesses of
this job, and try to understand what's blocking?

[Max Brustkern (nuclearbob)]

bootchart and anacron have stopped:
avahi-cups-reload stop/waiting
avahi-daemon start/running, process 743
mountall-net stop/waiting
mountnfs-bootclean.sh start/running
passwd stop/waiting
rc start/running, process 822
rsyslog start/running, process 510
startpar-bridge stop/waiting
tty4 start/running, process 823
udev start/running, process 284
upstart-udev-bridge start/running, process 277
ureadahead-other stop/waiting
whoopsie start/running, process 989
apport start/running
console-setup stop/waiting
hwclock-save stop/waiting
irqbalance stop/waiting
plymouth-log stop/waiting
systemd-logind start/running, process 662
tty5 start/running, process 827
failsafe stop/waiting
hybrid-gfx stop/waiting
modemmanager start/running, process 635
mountall.sh start/running
rfkill-store stop/waiting
dbus start/running, process 597
failsafe-x stop/waiting
mounted-var stop/waiting
plymouth-shutdown stop/waiting
plymouth stop/waiting
resolvconf start/running
ssh start/running, process 870
udev-fallback-graphics stop/waiting
checkroot.sh start/running
control-alt-delete stop/waiting
hwclock stop/waiting
mounted-proc stop/waiting
network-manager start/running, process 818
alsa-store stop/waiting
cups-browsed start/running, process 874
setvtrgb stop/waiting
shutdown stop/waiting
alsa-restore stop/waiting
cron start/running, process 895
lightdm start/running, process 906
mountall stop/waiting
mounted-debugfs stop/waiting
mountkernfs.sh start/running
console stop/waiting
mounted-run stop/waiting
acpid start/running, process 884
bluetooth start/running, process 673
checkfs.sh start/running
checkroot-bootclean.sh start/running
kmod stop/waiting
mountnfs.sh start/running
plymouth-stop stop/waiting
rcS stop/waiting
ufw start/running
wait-for-state stop/waiting
bootmisc.sh start/running
flush-early-job-log stop/waiting
friendly-recovery stop/waiting
rc-sysinit stop/waiting
cups start/running, process 770
pulseaudio stop/waiting
upstart-socket-bridge start/running, process 523
anacron stop/waiting
mountdevsubfs.sh start/running
tty2 start/running, process 835
udevtrigger stop/waiting
upstart-file-bridge start/running, process 480
container-detect stop/waiting
mounted-dev stop/waiting
mtab.sh start/running
tty3 start/running, process 836
udev-finish stop/waiting
alsa-state stop/waiting
hostname stop/waiting
mountall-reboot stop/waiting
mountall-shell stop/waiting
mounted-tmp stop/waiting
network-interface (lo) start/running
network-interface (eth0) start/running
network-interface (wlan1) start/running
network-interface (wlan0) start/running
plymouth-ready stop/waiting
plymouth-splash stop/waiting
plymouth-upstart-bridge stop/waiting
tty1 stop/waiting
udevmonitor stop/waiting
dmesg stop/waiting
mountall-bootclean.sh start/running
network-interface-security (network-manager) start/running
network-interface-security (network-interface/eth0) start/running
network-interface-security (network-interface/wlan0) start/running
network-interface-security (network-interface/wlan1) start/running
network-interface-security (network-interface/lo) start/running
network-interface-security (networking) start/running
networking start/running
procps stop/waiting
rfkill-restore stop/waiting
t...

[Max Brustkern (nuclearbob)]

Here's the pstree

[Max Brustkern (nuclearbob)]

Will rc keep running as long as rc.local is executing? We use rc.local in utah, so that could be the problem. Do we need to fork that?

[Max Brustkern (nuclearbob)]

Okay, we're not using rc.local any more, we use an xdg autostart script now.

[Steve Langasek (vorlon)]

Here's the relevant process tree:

root 826 0.0 0.0 4444 652 ? Ss 22:11 0:00 /bin/sh -e /proc/self/fd/9
root 857 0.0 0.0 4444 828 ? S 22:11 0:00 \_ /bin/sh /etc/init.d/rc 2
root 978 0.0 0.0 4444 804 ? S 22:11 0:00 \_ /bin/sh /etc/rc2.d/S99rc.local start
root 984 0.0 0.0 4444 648 ? S 22:11 0:00 \_ /bin/sh /etc/rc.local
root 985 9.9 4.0 155556 83000 ? S 22:11 0:12 \_ python /usr/bin/utah --resume -o /var/lib/utah/utah.out -r /var/lib/utah/master.run-reboot
root 1941 0.0 0.0 4444 652 ? S 22:11 0:00 \_ /bin/sh -c sudo -n -u root bash clean.sh

The problem is that utah is hooking into (and dynamically rewriting) /etc/rc.local, which blocks the rc job from finishing. So I think that's clearly a utah bug, not a ureadahead bug.