I've been optimizing my boot speed for fun. The last thing that I can't seem to figure out how to squeeze more speed out of is NFS.
$ systemd-analyze Startup finished in 968ms (kernel) + 2.840s (userspace) = 3.809s $ systemd-analyze blame 2.012s nfsd.service 121ms home-evan-documents.mount 104ms polkit.service 65ms systemd-modules-load.service
I looked around to see if I could enable socket activation for this, and I saw a patch floating around in late 2011, but it doesn't look like it ever made it in. Is there anyway to enable socket activation for this?
Or maybe someone can point me in the right direction for digging in to see why NFS is taking two seconds to come up?
Last edited by EvanPurkhiser (2014-04-20 06:50:43)
I have one system left that still uses a rotational drive. Even on there it only takes 209ms to complete. Maybe you should look at the logs about what it might be doing or waiting for during the startup.
Is your network startup also fast? I was using netctl to bring up my static ethernet connection before, and that actually took about two seconds and the NFS server started up in miliseconds. I switched to using systemd-networkd to bring up my network, but that seems to have shifted the bottleneck to nfs.
Here's my critical chain:
$ systemd-analyze critical-chain The time after the unit is active or started is printed after the "@" character. The time the unit takes to start is printed after the "+" character. graphical.target @2.849s └─multi-user.target @2.847s └─rpc-mountd.service @2.792s +53ms └─nfsd.service @773ms +2.013s └─rpcbind.service @751ms +16ms └─network.target @747ms └─systemd-networkd.service @726ms +5ms └─dbus.service @701ms └─basic.target @658ms └─timers.target @632ms └─logrotate.timer @605ms └─sysinit.target @496ms └─systemd-update-utmp.service @483ms +12ms └─systemd-tmpfiles-setup.service @477ms +4ms └─local-fs.target @476ms └─proc-fs-nfsd.mount @796ms └─system.slice @81ms └─-.slice @80ms
Last edited by EvanPurkhiser (2014-04-20 06:17:09)
Here's the log with debugging enabled. Unfortunately it doesn't seem to help too much
# journalctl -b --system -o short-precise --unit=nfsd.service -- Logs begin at Mon 2013-09-02 18:34:01 EDT, end at Sun 2014-04-20 02:06:11 EDT. -- Apr 20 02:05:39.856650 desktop systemd: Starting NFS Server Daemon... Apr 20 02:05:39.863286 desktop rpc.nfsd: rpc.nfsd: Checking netconfig for visible protocols. Apr 20 02:05:39.863540 desktop rpc.nfsd: rpc.nfsd: Enabling inet udp. Apr 20 02:05:39.864194 desktop rpc.nfsd: rpc.nfsd: Enabling inet tcp. Apr 20 02:05:39.864403 desktop rpc.nfsd: rpc.nfsd: Enabling inet6 udp. Apr 20 02:05:39.864604 desktop rpc.nfsd: rpc.nfsd: Enabling inet6 tcp. Apr 20 02:05:39.883605 desktop rpc.nfsd: rpc.nfsd: knfsd is currently down Apr 20 02:05:39.883907 desktop rpc.nfsd: rpc.nfsd: Writing version string to kernel: +4.1 -4.2 -2 +3 +4 Apr 20 02:05:39.892435 desktop rpc.nfsd: rpc.nfsd: Creating inet TCP socket. Apr 20 02:05:39.893102 desktop rpc.nfsd: rpc.nfsd: Creating inet UDP socket. Apr 20 02:05:39.901078 desktop rpc.nfsd: rpc.nfsd: Creating inet6 TCP socket. Apr 20 02:05:39.901296 desktop rpc.nfsd: rpc.nfsd: Creating inet6 UDP socket. Apr 20 02:05:41.875478 desktop systemd: Started NFS Server Daemon.
I can't tell if it's hanging on creating that last inet6 UDP socket, or if there are other things happening after that aren't logged. I assume more things are happening causing it to hang.
My intuition is telling me it's doing something over the network.
Edit: Disabling UDP with the -U flag doesn't help. It's still waiting for something
Apr 20 02:14:46.878586 desktop rpc.nfsd: rpc.nfsd: Creating inet TCP socket. Apr 20 02:14:46.881353 desktop rpc.nfsd: rpc.nfsd: Creating inet6 TCP socket. Apr 20 02:14:48.876813 desktop systemd: Started NFS Server Daemon.
Any ideas as to how to get more debug information out of this thing is appreciated!
Edit again: Here are some other things happening in between those two messages:
Apr 20 02:14:46.881353 desktop rpc.nfsd: rpc.nfsd: Creating inet6 TCP socket. Apr 20 02:14:46.889442 desktop kernel: NFSD: starting 90-second grace period (net ffffffff81895f80) Apr 20 02:14:46.986194 desktop kernel: hub 1-1:1.0: USB hub found Apr 20 02:14:46.986370 desktop kernel: hub 1-1:1.0: 6 ports detected Apr 20 02:14:47.092784 desktop kernel: usb 4-1: new high-speed USB device number 2 using ehci-pci Apr 20 02:14:47.216188 desktop kernel: hub 4-1:1.0: USB hub found Apr 20 02:14:47.216971 desktop kernel: hub 4-1:1.0: 8 ports detected Apr 20 02:14:47.482792 desktop kernel: usb 4-1.4: new high-speed USB device number 3 using ehci-pci Apr 20 02:14:47.482940 desktop kernel: Switched to clocksource tsc Apr 20 02:14:47.566200 desktop kernel: hub 4-1.4:1.0: USB hub found Apr 20 02:14:47.566380 desktop kernel: hub 4-1.4:1.0: 4 ports detected Apr 20 02:14:47.832777 desktop kernel: usb 4-1.4.4: new high-speed USB device number 4 using ehci-pci Apr 20 02:14:47.916174 desktop kernel: hub 4-1.4.4:1.0: USB hub found Apr 20 02:14:47.916348 desktop kernel: hub 4-1.4.4:1.0: 7 ports detected Apr 20 02:14:48.182750 desktop kernel: usb 4-22.214.171.124: new low-speed USB device number 5 using ehci-pci Apr 20 02:14:48.319421 desktop kernel: hidraw: raw HID events driver (C) Jiri Kosina Apr 20 02:14:48.352733 desktop kernel: usbcore: registered new interface driver usbhid Apr 20 02:14:48.352828 desktop kernel: usbhid: USB HID core driver Apr 20 02:14:48.352889 desktop kernel: input: USB Keyboard as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.4/4-1.4.4/4-126.96.36.199/4-188.8.131.52:1.0/0003:04D9:1818.0001/input/input10 Apr 20 02:14:48.353170 desktop kernel: hid-generic 0003:04D9:1818.0001: input,hidraw0: USB HID v1.10 Keyboard [USB Keyboard] on usb-0000:00:1d.0-184.108.40.206/input0 Apr 20 02:14:48.353258 desktop kernel: input: USB Keyboard as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.4/4-1.4.4/4-220.127.116.11/4-18.104.22.168:1.1/0003:04D9:1818.0002/input/input11 Apr 20 02:14:48.353425 desktop kernel: hid-generic 0003:04D9:1818.0002: input,hidraw1: USB HID v1.10 Device [USB Keyboard] on usb-0000:00:1d.0-22.214.171.124/input1 Apr 20 02:14:48.362765 desktop kernel: usb 4-126.96.36.199: new high-speed USB device number 6 using ehci-pci Apr 20 02:14:48.512762 desktop kernel: usb 4-188.8.131.52: new full-speed USB device number 7 using ehci-pci Apr 20 02:14:48.636068 desktop kernel: usb_audio: Warning! Unlikely big volume range (=464), cval->res is probably wrong. Apr 20 02:14:48.636197 desktop kernel: usb_audio:  FU [Mic Playback Volume] ch = 1, val = -10496/-3072/16 Apr 20 02:14:48.648338 desktop systemd-networkd: enp6s0: carrier on Apr 20 02:14:48.649502 desktop kernel: alx 0000:06:00.0 enp6s0: NIC Up: 1 Gbps Full Apr 20 02:14:48.649598 desktop kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp6s0: link becomes ready Apr 20 02:14:48.666070 desktop kernel: usbcore: registered new interface driver snd-usb-audio Apr 20 02:14:48.666184 desktop kernel: usb 4-184.108.40.206: new full-speed USB device number 8 using ehci-pci Apr 20 02:14:48.799404 desktop kernel: input: Razer Razer Naga as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.4/4-1.4.4/4-220.127.116.11/4-18.104.22.168:1.0/0003:1532:0015.0003/input/input12 Apr 20 02:14:48.800050 desktop kernel: hid-generic 0003:1532:0015.0003: input,hidraw2: USB HID v1.11 Mouse [Razer Razer Naga] on usb-0000:00:1d.0-22.214.171.124/input0 Apr 20 02:14:48.826077 desktop kernel: input: Razer Razer Naga as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.4/4-1.4.4/4-126.96.36.199/4-188.8.131.52:1.1/0003:1532:0015.0004/input/input13 Apr 20 02:14:48.826264 desktop kernel: hid-generic 0003:1532:0015.0004: input,hidraw3: USB HID v1.11 Keyboard [Razer Razer Naga] on usb-0000:00:1d.0-184.108.40.206/input1 Apr 20 02:14:48.842741 desktop kernel: mousedev: PS/2 mouse device common for all mice Apr 20 02:14:48.876813 desktop systemd: Started NFS Server Daemon.
most notable seems to be `systemd-networkd: enp6s0: carrier on`
Last edited by EvanPurkhiser (2014-04-20 06:24:12)
I have been using systemd-networkd on this particular machine to get an address via dhcp. But even though it is fast, it still took a reported 922ms to start on last boot. So I don't think that this should have any bearing on nfsd.
Do you actually have ipv6 set up and in use?
I just solved this
The problem was DNS resolution of hostnames. I have an export that looks like this:
# Share media with my HTPC /home/evan/documents/multimedia htpc(ro,no_root_squash,insecure,no_subtree_check)
Resolving the hostname 'htpc' on my routers DNS server is where all the time went.
$ host htpc htpc has address 192.168.1.101
Edit /etc/exports.d/multimedia.exports to:
# Share media with my HTPC /home/evan/documents/multimedia 192.168.1.101(ro,no_root_squash,insecure,no_subtree_check)
fixes the issue
$ systemd-analyze Startup finished in 973ms (kernel) + 903ms (userspace) = 1.877s
It would be nice to keep the hostname in their instead of a IP in case I ever decide to change it or make it dynamic. Maybe there's something I can install that will persistently cache DNS requests to my router?
Just put it in your /etc/hosts file and it should speed things up.