8 minute Upstart delay during LTSP client boot

Matthew Wyneken wyneken at physik.uni-freiburg.de
Wed Nov 14 15:17:18 UTC 2012 

On 13.11.2012, at 18:20, James Hunt wrote:

> I took a quick look at nbd-proxy.c as used by the client and it appears to call
> sleep() if it detects a connection delay. There is a debug flag for nbd-proxy
> which might be useful.

As far as I can tell from Internet research, nbd-proxy is not started by default. I couldn't find it running anywhere either. Just to be on the safe side, I moved the nbd-proxy binary and the nbd-client-proxy script out of the way, both on the initramfs and on the root fs. That had no effect.

I've had problems with nbd-proxy in the past so I immediately thought of it. As far as I can tell, though,  it's not being run.

I can't even find a place to specify the debug flag for nbd-proxy.

> Try booting adding "debug" on the kernel command-line, then taking a look in
> /run/initramfs/initramfs.debug.

Here the contents of /run/initramfs/initramfs.debug:

+ [ -n  ]
+ resume=
+ maybe_break top
+ echo 
+ egrep -q (,|^)top(,|$)
+ export BOOT
+ run_scripts /scripts/init-top
+ initdir=/scripts/init-top
+ [ ! -d /scripts/init-top ]
+ [ -f /scripts/init-top/ORDER ]
+ . /scripts/init-top/ORDER
+ /scripts/init-top/all_generic_ide
+ [ -e /conf/param.conf ]
+ /scripts/init-top/blacklist
+ [ -e /conf/param.conf ]
+ /scripts/init-top/keymap
+ [ -e /conf/param.conf ]
+ /scripts/init-top/udev
+ [ -e /conf/param.conf ]
+ /scripts/init-top/framebuffer
+ [ -e /conf/param.conf ]
+ /scripts/init-top/console_setup
+ [ -e /conf/param.conf ]
+ /scripts/init-top/brltty
+ [ -e /conf/param.conf ]
+ /scripts/init-top/plymouth
error: unexpectedly disconnected from boot status daemon
+ [ -e /conf/param.conf ]
+ maybe_break modules
+ echo 
+ egrep -q (,|^)modules(,|$)
+ [ n != y ]
+ log_begin_msg Loading essential drivers
+ _log_msg Begin: Loading essential drivers ... 
+ [ n = y ]
+ printf Begin: Loading essential drivers ... 
Begin: Loading essential drivers ... + load_modules
+ [ -e /conf/modules ]
+ cat /conf/modules
+ read m
+ [ -z nbd ]
+ printf %.1s nbd
+ com=n
+ [ n = # ]
+ modprobe nbd
+ read m
+ [ -z squashfs ]
+ printf %.1s squashfs
+ com=s
+ [ s = # ]
+ modprobe squashfs
+ read m
+ [ -z overlayfs ]
+ printf %.1s overlayfs
+ com=o
+ [ o = # ]
+ modprobe overlayfs
+ read m
+ [ -z aufs ]
+ printf %.1s aufs
+ com=a
+ [ a = # ]
+ modprobe aufs
+ read m
+ [ -z nbd ]
+ printf %.1s nbd
+ com=n
+ [ n = # ]
+ modprobe nbd
+ read m
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ [ -n  ]
+ maybe_break premount
+ echo 
+ egrep -q (,|^)premount(,|$)
+ [ n != y ]
+ log_begin_msg Running /scripts/init-premount
+ _log_msg Begin: Running /scripts/init-premount ... 
+ [ n = y ]
+ printf Begin: Running /scripts/init-premount ... 
Begin: Running /scripts/init-premount ... + run_scripts /scripts/init-premount
+ initdir=/scripts/init-premount
+ [ ! -d /scripts/init-premount ]
+ [ -f /scripts/init-premount/ORDER ]
+ . /scripts/init-premount/ORDER
+ /scripts/init-premount/udhcp
DHCP request for eth0...
Done.
eth0 configured at 132.230.78.32:132.230.78.27:132.230.78.254:255.255.255.0:tlin12
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ export DEVICE=eth0
+ export IPV4ADDR=132.230.78.32
+ export IPV4NETMASK=255.255.255.0
+ export IPV4GATEWAY=132.230.78.254
+ export IPV4DNS0=132.230.200.200
+ export IPV4DNS1=132.230.201.111
+ export HOSTNAME=tlin12
+ export ROOTSERVER=132.230.78.27
+ export filename=/ltsp/pxelinux.0
+ export DNS_SERVER=132.230.200.200 132.230.201.111
+ /scripts/init-premount/brltty
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ export DEVICE=eth0
+ export IPV4ADDR=132.230.78.32
+ export IPV4NETMASK=255.255.255.0
+ export IPV4GATEWAY=132.230.78.254
+ export IPV4DNS0=132.230.200.200
+ export IPV4DNS1=132.230.201.111
+ export HOSTNAME=tlin12
+ export ROOTSERVER=132.230.78.27
+ export filename=/ltsp/pxelinux.0
+ export DNS_SERVER=132.230.200.200 132.230.201.111
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ maybe_break mount
+ echo 
+ egrep -q (,|^)mount(,|$)
+ log_begin_msg Mounting root file system
+ _log_msg Begin: Mounting root file system ... 
+ [ n = y ]
+ printf Begin: Mounting root file system ... 
Begin: Mounting root file system ... + . /scripts/local
+ parse_numeric /dev/nbd0
+ return
+ maybe_break mountroot
+ echo 
+ egrep -q (,|^)mountroot(,|$)
+ mountroot
+ pre_mountroot
+ [ n != y ]
+ log_begin_msg Running /scripts/local-top
+ _log_msg Begin: Running /scripts/local-top ... 
+ [ n = y ]
+ printf Begin: Running /scripts/local-top ... 
Begin: Running /scripts/local-top ... + run_scripts /scripts/local-top
+ initdir=/scripts/local-top
+ [ ! -d /scripts/local-top ]
+ [ -f /scripts/local-top/ORDER ]
+ . /scripts/local-top/ORDER
+ /scripts/local-top/nbd
Begin: Setting up nbd-client ... Negotiation: ..size = 2697MB
bs=1024, sz=2828824576 bytes
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ export DEVICE=eth0
+ export IPV4ADDR=132.230.78.32
+ export IPV4NETMASK=255.255.255.0
+ export IPV4GATEWAY=132.230.78.254
+ export IPV4DNS0=132.230.200.200
+ export IPV4DNS1=132.230.201.111
+ export HOSTNAME=tlin12
+ export ROOTSERVER=132.230.78.27
+ export filename=/ltsp/pxelinux.0
+ export DNS_SERVER=132.230.200.200 132.230.201.111
+ /scripts/local-top/nbd_ltsp
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ [ /nbd0 = /dev/nbd0 ]
+ [ -z squashfs ]
+ [ -z squashfs -a ! -e /dev/nbd0 ]
+ [ -z  ]
+ [ -n squashfs ]
+ ROOTFSTYPE=squashfs
+ [ n != y ]
+ log_begin_msg Running /scripts/local-premount
+ _log_msg Begin: Running /scripts/local-premount ... 
+ [ n = y ]
+ printf Begin: Running /scripts/local-premount ... 
Begin: Running /scripts/local-premount ... + run_scripts /scripts/local-premount
+ initdir=/scripts/local-premount
+ [ ! -d /scripts/local-premount ]
+ [ -f /scripts/local-premount/ORDER ]
+ . /scripts/local-premount/ORDER
+ /scripts/local-premount/fixrtc
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ /scripts/local-premount/ntfs_3g
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ /scripts/local-premount/resume
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ [ y = y ]
+ [ -z  ]
+ roflag=-r
+ [ -n squashfs ]
+ modprobe squashfs
+ mount -r -t squashfs /dev/nbd0 /root
+ mountroot_status=0
+ [  ]
+ [ n != y ]
+ log_begin_msg Running /scripts/local-bottom
+ _log_msg Begin: Running /scripts/local-bottom ... 
+ [ n = y ]
+ printf Begin: Running /scripts/local-bottom ... 
Begin: Running /scripts/local-bottom ... + run_scripts /scripts/local-bottom
+ initdir=/scripts/local-bottom
+ [ ! -d /scripts/local-bottom ]
+ [ -f /scripts/local-bottom/ORDER ]
+ . /scripts/local-bottom/ORDER
+ /scripts/local-bottom/ntfs_3g
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ maybe_break bottom
+ echo 
+ egrep -q (,|^)bottom(,|$)
+ [ n != y ]
+ log_begin_msg Running /scripts/init-bottom
+ _log_msg Begin: Running /scripts/init-bottom ... 
+ [ n = y ]
+ printf Begin: Running /scripts/init-bottom ... 
Begin: Running /scripts/init-bottom ... + run_scripts /scripts/init-bottom
+ initdir=/scripts/init-bottom
+ [ ! -d /scripts/init-bottom ]
+ [ -f /scripts/init-bottom/ORDER ]
+ . /scripts/init-bottom/ORDER
+ /scripts/init-bottom/ltsp
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ /scripts/init-bottom/udev
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ /scripts/init-bottom/plymouth
+ [ -e /conf/param.conf ]
+ . /conf/param.conf
+ FSTYPE=squashfs
+ [ n != y ]
+ log_end_msg
+ _log_msg done.\n
+ [ n = y ]
+ printf done.\n
done.
+ [ -d /root/run ]
+ mount -n -o move /run /root/run
+ echo

+ echo !!! HERE I AM
!!! HERE I AM
+ echo

+ set -x
+ mount -n -o move /sys /root/sys
+ mount -n -o move /proc /root/proc
+ [ -n /sbin/init-ltsp ]
+ validate_init /sbin/init-ltsp
+ checktarget=/sbin/init-ltsp
+ [ -d /root ]
+ [ -h /root/sbin/init-ltsp ]
+ [ ! -x /root/sbin/init-ltsp ]
+ [ -d /root/sbin/init-ltsp ]
+ [ ! -x /root/sbin/init ]
+ maybe_break init
+ echo 
+ egrep -q (,|^)init(,|$)
+ unset debug
+ unset MODPROBE_OPTIONS
+ unset DPKG_ARCH
+ unset ROOTFLAGS
+ unset ROOTFSTYPE
+ unset ROOTDELAY
+ unset ROOT
+ unset IP
+ unset BOOT
+ unset BOOTIF
+ unset UBIMTD
+ unset blacklist
+ unset break
+ unset noresume
+ unset panic
+ unset quiet
+ unset readonly
+ unset resume
+ unset resume_offset
+ exec run-init /root /sbin/init-ltsp debug

The "HERE I AM" lines are debugging lines I put in some script somewhere days ago. I'll have to clean that up when I'm done.

The delay I see definitely occurs after init-ltsp is execed. init-ltsp also completes without any problems as far as I can see. The delay occurs at the last line of init-ltsp when it execs init. That's why I thought that this might be an upstart problem.

I think my next step will be to try some package sniffing to see if I can find anything.

--
Matthew

More information about the upstart-devel mailing list