[Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

EvanPurkhiser · 2014-04-20 05:27:30

Hey guys,

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)

WonderWoofy · 2014-04-20 05:53:14

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.

EvanPurkhiser · 2014-04-20 05:58:01

Thanks WonderWoofy,

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)

EvanPurkhiser · 2014-04-20 06:12:44

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[1]: Starting NFS Server Daemon...
Apr 20 02:05:39.863286 desktop rpc.nfsd[306]: rpc.nfsd: Checking netconfig for visible protocols.
Apr 20 02:05:39.863540 desktop rpc.nfsd[306]: rpc.nfsd: Enabling inet udp.
Apr 20 02:05:39.864194 desktop rpc.nfsd[306]: rpc.nfsd: Enabling inet tcp.
Apr 20 02:05:39.864403 desktop rpc.nfsd[306]: rpc.nfsd: Enabling inet6 udp.
Apr 20 02:05:39.864604 desktop rpc.nfsd[306]: rpc.nfsd: Enabling inet6 tcp.
Apr 20 02:05:39.883605 desktop rpc.nfsd[306]: rpc.nfsd: knfsd is currently down
Apr 20 02:05:39.883907 desktop rpc.nfsd[306]: rpc.nfsd: Writing version string to kernel: +4.1 -4.2 -2 +3 +4
Apr 20 02:05:39.892435 desktop rpc.nfsd[306]: rpc.nfsd: Creating inet TCP socket.
Apr 20 02:05:39.893102 desktop rpc.nfsd[306]: rpc.nfsd: Creating inet UDP socket.
Apr 20 02:05:39.901078 desktop rpc.nfsd[306]: rpc.nfsd: Creating inet6 TCP socket.
Apr 20 02:05:39.901296 desktop rpc.nfsd[306]: rpc.nfsd: Creating inet6 UDP socket.
Apr 20 02:05:41.875478 desktop systemd[1]: 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[306]: rpc.nfsd: Creating inet TCP socket.
Apr 20 02:14:46.881353 desktop rpc.nfsd[306]: rpc.nfsd: Creating inet6 TCP socket.
Apr 20 02:14:48.876813 desktop systemd[1]: 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[306]: 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-1.4.4.1: 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-1.4.4.1/4-1.4.4.1: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-1.4.4.1/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-1.4.4.1/4-1.4.4.1: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-1.4.4.1/input1
Apr 20 02:14:48.362765 desktop kernel: usb 4-1.4.4.4: new high-speed USB device number 6 using ehci-pci
Apr 20 02:14:48.512762 desktop kernel: usb 4-1.4.4.5: 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: [6] FU [Mic Playback Volume] ch = 1, val = -10496/-3072/16
Apr 20 02:14:48.648338 desktop systemd-networkd[297]: 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-1.4.4.6: 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-1.4.4.6/4-1.4.4.6: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-1.4.4.6/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-1.4.4.6/4-1.4.4.6: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-1.4.4.6/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[1]: Started NFS Server Daemon.

most notable seems to be `systemd-networkd[297]: enp6s0: carrier on`

Last edited by EvanPurkhiser (2014-04-20 06:24:12)

WonderWoofy · 2014-04-20 06:46:57

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?

EvanPurkhiser · 2014-04-20 06:49:56

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?

WonderWoofy · 2014-04-20 18:54:23

Just put it in your /etc/hosts file and it should speed things up.

Arch Linux

#1 2014-04-20 05:27:30

[Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#2 2014-04-20 05:53:14

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#3 2014-04-20 05:58:01

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#4 2014-04-20 06:12:44

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#5 2014-04-20 06:46:57

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#6 2014-04-20 06:49:56

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

#7 2014-04-20 18:54:23

Re: [Solved] Speed up nfsd.service (rpc-mountd + rpc-idmapd) on boot

Board footer