vboxadd.service startup times out on Fedora 22 boot

[William Meier]

I recently started getting the following when booting my Fedora 22 guest system on my Windows 7 host.

[...] systemd[1]: vboxadd.service start operation timed out. Terminating.
[...] systemd[1]: Failed to start VirtualBox Linux Additions kernel modules.
[...] systemd[1]: Unit vboxadd.service entered failed state.
[...] systemd[1]: vboxadd.service failed.

After some poking around I determined that the timeout occurred while executing the following in the vboxadd init script:

    if $MODPROBE -c 2>/dev/null | grep -q '^allow_unsupported_modules  *0'; then
      MODPROBE="$MODPROBE --allow-unsupported-modules"
    fi

I changed the timeout specified in the vboxadd.service config file from 5 minutes to 10 minutes and the timeout no longer occurred.

I should note that this timeout started happening only after some recent Fedora 22 updates. I had no problems previously.

[Frank Mehnert]

Can you run

time modprobe -c

as root and tell me the resulting real time? How many RAM did you configure for your Fedora 22 guest?

[William Meier]

I'm running 32 bits Windows/Fedora with the VBox client configured for 896Megs of memory and 1 CPU. I'm running on a fairly old Windows machine: Intel Core 2 1.5 GHz with 4G of memory.

The Fedora boot takes multiple minutes, but once booted the system is reasonably responsive and is OK for what I need to do (building/testing Wireshark).

Note: CPU in the client maxes out at 100% for all the cases below wherein the modprobe output is being piped to another process.

Interestingly enough: writing the modprobe output to a file and then grepping the file takes *much* less time.

So: Is this really some non-optimal config in my Fedora ? I've no idea.

# time modprobe -c
[...]
real	1m2.524s
user	0m0.030s
sys	0m9.096s

# time (modprobe -c | wc -l)
24245

real	2m23.874s
user	0m0.217s
sys	1m4.982s

# time (modprobe -c | grep -q "^allow")

real	2m5.764s
user	0m0.270s
sys	0m59.729s

[root@localhost ~]# time grep "^allow" <(modprobe -c)

real	2m28.086s
user	0m0.062s
sys	0m18.242s


# ## Writing to a file and then grepping from the file goes much faster ??
# ## Interesting ....
# time modprobe -c > foo.txt

real	0m6.550s
user	0m0.021s
sys	0m4.513s

# time (cat foo.txt | grep "^allow")

real	0m0.218s
user	0m0.003s
sys	0m0.084s

# time grep "^allow" <(cat foo.txt)

real	0m0.543s
user	0m0.010s
sys	0m0.103s

[William Meier]

I'm no Linux expert but I imagine that the fact that modprobe apparently does 4 "write" system calls per line of output might be a reason for slowness.

strace -T -p [...]   ## tracing modprobe process outputting to a pipe
[...]
write(1, "alias pci:v00008086d00001557sv*s"..., 42) = 42 <0.001537>
write(1, " ", 1)        = 1 <0.001705>
write(1, "ixgbe", 5)    = 5 <0.002706>
write(1, "\n", 1)       = 1 <0.004119>
write(1, "alias pci:v00008086d00001558sv*s"..., 42) = 42 <0.002049>
write(1, " ", 1)        = 1 <0.001955>
write(1, "ixgbe", 5)    = 5 <0.007699>
write(1, "\n", 1)       = 1 <0.012601>
[...]

[William Meier]

Still a problem with VirtualBox 5.08 and Fedora 23.

There must be a better (quicker) way in the /opt/VBoxGuestAdditions-5.0.8/init/vboxadd script to accomplish what the if $MODPROBE -c ... | grep ... code is doing.

Write to a temporary file ?

[Michael Thayer]

Just tried this on my Ubuntu 15.10 host:

# time (modprobe -c | grep -q "!^allow")

real	0m0.073s
user	0m0.036s
sys	0m0.096s

And on an Ubuntu 15.04 guest:

# time (modprobe -c | grep -q "!^allow")

real	0m0.078s
user	0m0.028s
sys	0m0.060s

I think that this requires a bit of investigation on your part about why it is happening. Things to try would include installing another Fedora guest (or others), trying to find out what the update was which caused this, trying to find reports of similar things and asking Fedora people if they can explain it.