Re: 7.0 slow multiuser boot

On Sun, 25 Jan 2015 08:40:44 +0000 (UTC)
[email protected] (Michael van Elst) wrote:

> >What happened there?
> 
> How often did you measure the startup time?

An exact measurement was done only three or four times, but I noticed 7.0's
slow startup since weeks.


> The first time you start
> the new sshd, it computes another hostkey which takes a very long time.

Sure. I would have noticed that. :)
No sshd enabled. Also makemandb disabled.


> On a system that is about as fast, with a gcc-4.8-compiled but
> otherwise pretty generic -current from December, I see the following
> for the rc scripts, the kernel booting into single user before took
> another ~30 seconds for a total startup time of about 4 minutes.

Ok. I admit 9 minutes are an exaggeration. Your timings are a little bit
faster, but not so different to mine. Now I measured the times amd memory
usage exactly, by applying the following patch to /etc/rc:

--- /etc/rc.orig        2015-01-16 10:47:54.000000000 +0100
+++ /etc/rc     2015-01-25 15:15:56.000000000 +0100
@@ -306,7 +306,9 @@
        cmd-name)
                # Marks the start of a child script (usually one of
                # the /etc/rc.d/* scripts).
-               rc_log_message "[running $1]"
+               mytm=`/bin/date +%H:%M:%S`
+               myvm=`/usr/bin/vmstat | grep -v lt | cut -c 7-21`
+               rc_log_message "$mytm [running $1] $myvm"
                ;;
        cmd-status)
                # Marks the end of a child script.


Then I compared 6.1.5 and 7.0 on the same machine (A4000, 68060/50, IDE)
with the same configuration (i.e. no sshd no makemandb).

First NetBSD 6.1.5. Takes 2 minutes and 39 seconds:
(vmstat output is missing first, because /usr is on a separate filesystem)

---8<---
[/etc/rc starting at Sun Jan 25 15:54:11 GMT 2015]
15:54:12 [running rcorder] 
15:54:13 [running /etc/rc.d/wdogctl] 
15:54:14 [running /etc/rc.d/fsck_root] 
Starting root file system check:
/dev/rwd0a: file system is clean; not checking
15:54:15 [running /etc/rc.d/root] 
15:54:16 [running /etc/rc.d/ccd] 
15:54:16 [running /etc/rc.d/rndctl] 
15:54:17 [running /etc/rc.d/cgd] 
[NOTE: Output from /etc/rc.d/cgd is not logged]
15:54:17 [running /etc/rc.d/lvm] 
15:54:18 [running /etc/rc.d/raidframe] 
15:54:19 [running /etc/rc.d/DISKS] 
15:54:19 [running /etc/rc.d/swap1] 
swapctl: adding /dev/wd0b as swap device at priority 0
15:54:20 [running /etc/rc.d/fsck] 
Starting file system checks:
/dev/rwd0e: file system is clean; not checking
/dev/rwd0f: file system is clean; not checking
15:54:20 [running /etc/rc.d/mountcritlocal] 
[NOTE: Optional file system /var is not present]
15:54:21 [running /etc/rc.d/ttys] 
Setting tty flags.
15:54:22 [running /etc/rc.d/bootconf.sh] 
[NOTE: Output from /etc/rc.d/bootconf.sh is not logged]
15:54:22 [running /etc/rc.d/pf_boot] 
15:54:23 [running /etc/rc.d/ipsec] 
15:54:23 [running /etc/rc.d/ipfilter] 
15:54:24 [running /etc/rc.d/sysctl] 
Setting sysctl variables:
ddb.onpanic: 1 -> 0
15:54:25 [running /etc/rc.d/network] 
Starting network.
Hostname: aquila
IPv6 mode: host
Configuring network interfaces: le0.
Adding interface aliases:.
add net default: gateway 192.168.0.254
15:54:30 [running /etc/rc.d/wpa_supplicant] 
15:54:30 [running /etc/rc.d/dhclient] 
15:54:31 [running /etc/rc.d/dhcpcd] 
15:54:31 [running /etc/rc.d/ldpd] 
15:54:32 [running /etc/rc.d/npf] 
15:54:32 [running /etc/rc.d/pf] 
15:54:33 [running /etc/rc.d/route6d] 
15:54:33 [running /etc/rc.d/routed]    5960  82008 
16:54:36 [running /etc/rc.d/rtsold]    6200  81168 
16:54:38 [running /etc/rc.d/staticroute]    6368  80528 
16:54:39 [running /etc/rc.d/NETWORKING]    6440  80264 
16:54:41 [running /etc/rc.d/mountcritremote]    5808  80840 
16:54:42 [running /etc/rc.d/sysdb]    5648  81040 
Building databases: dev, utmp, utmpx.
16:54:43 [running /etc/rc.d/newsyslog]    5800  80856 
16:54:45 [running /etc/rc.d/wscons]    6016  80608 
16:54:46 [running /etc/rc.d/syslogd]    6224  80328 
Starting syslogd.
16:54:50 [running /etc/rc.d/ppp]    7472  79056 
16:54:51 [running /etc/rc.d/named]    7336  79224 
16:54:52 [running /etc/rc.d/rtclocaltime]    7656  78792 
16:54:54 [running /etc/rc.d/ntpdate]    7632  78840 
16:54:56 [running /etc/rc.d/rpcbind]    7520  78992 
16:54:57 [running /etc/rc.d/ypserv]    7664  78728 
16:54:58 [running /etc/rc.d/ypbind]    8368  77960 
16:55:00 [running /etc/rc.d/yppasswdd]    8576  77752 
16:55:01 [running /etc/rc.d/mountall]    8640  77688 
Mounting all filesystems...
16:55:03 [running /etc/rc.d/perusertmp]    8656  77672 
16:55:05 [running /etc/rc.d/cleartmp]    8752  77576 
Clearing temporary files.
16:55:06 [running /etc/rc.d/xfs]    8928  77336 
16:55:07 [running /etc/rc.d/accounting]    8936  77328 
16:55:08 [running /etc/rc.d/amd]    8960  77304 
16:55:09 [running /etc/rc.d/dmesg]    8976  77288 
16:55:10 [running /etc/rc.d/fccache]    8992  77272 
Updating fontconfig cache: done.
16:55:13 [running /etc/rc.d/veriexec]    8304  77944 
16:55:13 [running /etc/rc.d/ldconfig]    8888  77248 
Creating a.out runtime link editor directory cache.
16:55:18 [running /etc/rc.d/quota]    9944  75952 
Checking quotas: done.
16:55:20 [running /etc/rc.d/mountd]    9992  75904 
16:55:21 [running /etc/rc.d/nfsd]   10336  75456 
16:55:22 [running /etc/rc.d/nfslocking]   10568  75192 
16:55:24 [running /etc/rc.d/pwcheck]   10624  75176 
16:55:26 [running /etc/rc.d/gpio]   10184  75672 
16:55:28 [running /etc/rc.d/random_seed]   10208  75648 
Loaded entropy from disk.
16:55:29 [running /etc/rc.d/ipnat]   10584  75200 
16:55:30 [running /etc/rc.d/securelevel]   10584  75200 
Setting securelevel: kern.securelevel: 0 -> 1
16:55:32 [running /etc/rc.d/swap2]   10616  75168 
16:55:33 [running /etc/rc.d/virecover]   10616  75168 
Starting virecover.
16:55:34 [running /etc/rc.d/altqd]   10256  75592 
16:55:35 [running /etc/rc.d/ifwatchd]   10256  75592 
16:55:36 [running /etc/rc.d/isdnd]   10256  75592 
16:55:37 [running /etc/rc.d/ipfs]   10256  75592 
16:55:39 [running /etc/rc.d/ipmon]   10448  75360 
16:55:40 [running /etc/rc.d/kdc]   10784  74944 
16:55:41 [running /etc/rc.d/pflogd]   10336  75496 
16:55:43 [running /etc/rc.d/racoon]   10336  75496 
16:55:44 [running /etc/rc.d/savecore]   10848  74880 
Checking for core dump...
savecore: no core dump
16:55:46 [running /etc/rc.d/SERVERS]   10528  75224 
16:55:47 [running /etc/rc.d/DAEMON]   11688  73992 
16:55:49 [running /etc/rc.d/apmd]   12728  72888 
16:55:51 [running /etc/rc.d/bluetooth]   13264  72352 
16:55:53 [running /etc/rc.d/bootparams]   13272  72304 
16:55:56 [running /etc/rc.d/dhcpd]   14000  71512 
16:55:57 [running /etc/rc.d/dhcrelay]   14208  71304 
16:55:58 [running /etc/rc.d/ftp_proxy]   14528  70896 
16:56:00 [running /etc/rc.d/irdaattach]   14688  70680 
16:56:02 [running /etc/rc.d/local]   14224  71200 
Starting local daemons:.
16:56:04 [running /etc/rc.d/lpd]   14360  71064 
16:56:05 [running /etc/rc.d/makemandb]   14360  71064 
16:56:07 [running /etc/rc.d/mopd]   14544  70880 
16:56:07 [running /etc/rc.d/motd]   14224  71200 
Updating motd.
16:56:10 [running /etc/rc.d/mrouted]   14544  70880 
16:56:11 [running /etc/rc.d/ntpd]   14224  71200 
16:56:13 [running /etc/rc.d/powerd]   14384  71040 
16:56:15 [running /etc/rc.d/rarpd]   14544  70880 
16:56:16 [running /etc/rc.d/rbootd]   14008  71368 
16:56:18 [running /etc/rc.d/rtadvd]   14016  71352 
16:56:19 [running /etc/rc.d/rwho]   14016  71336 
16:56:20 [running /etc/rc.d/screenblank]   14016  71336 
16:56:21 [running /etc/rc.d/timed]   14016  71248 
16:56:23 [running /etc/rc.d/tpctl]   14024  71168 
16:56:24 [running /etc/rc.d/LOGIN]   14024  71088 
16:56:25 [running /etc/rc.d/xdm]   14032  71080 
16:56:27 [running /etc/rc.d/wsmoused]   14032  71080 
16:56:28 [running /etc/rc.d/sshd]   14032  71048 
16:56:29 [running /etc/rc.d/raidframeparity]   14032  71048 
16:56:31 [running /etc/rc.d/postfix]   14032  71040 
16:56:41 [running /etc/rc.d/ndbootd]   13240  71808 
16:56:42 [running /etc/rc.d/moused]   13520  71528 
16:56:43 [running /etc/rc.d/mixerctl]   13840  71208 
16:56:44 [running /etc/rc.d/mdnsd]   14248  70736 
16:56:46 [running /etc/rc.d/isibootd]   15320  69520 
16:56:49 [running /etc/rc.d/iscsi_target]   16360  68520 
16:56:50 [running /etc/rc.d/inetd]   16368  68512 
Starting inetd.
16:56:51 [running /etc/rc.d/identd]   16368  68512 
16:56:52 [running /etc/rc.d/httpd]   16368  68512 
16:56:53 [running /etc/rc.d/hostapd]   16368  68512 
16:56:54 [running /etc/rc.d/ftpd]   16368  68512 
16:56:55 [running /etc/rc.d/envsys]   16368  68512 
16:56:56 [running /etc/rc.d/cron]   16368  68512 
Starting cron.
[/etc/rc finished at Sun Jan 25 16:56:50 CET 2015]
[/etc/rc exiting with status 0]
---8<---


Now NetBSD 7.0beta (from last week). Takes 4 minutes and 51 seconds.

---8<---
[/etc/rc starting at Sun Jan 25 16:33:15 CET 2015]
16:33:17 [running rcorder]    5040  84664 
16:33:20 [running /etc/rc.d/wdogctl]    5656  84056 
16:33:22 [running /etc/rc.d/fsck_root]    5600  84112 
Starting root file system check:
/dev/rwd1a: file system is clean; not checking
16:33:24 [running /etc/rc.d/root]    5624  84040 
16:33:26 [running /etc/rc.d/ccd]    6424  83128 
16:33:28 [running /etc/rc.d/rndctl]    6096  83488 
16:33:29 [running /etc/rc.d/cgd]    5688  83960 
[NOTE: Output from /etc/rc.d/cgd is not logged]
16:33:32 [running /etc/rc.d/lvm]    5672  83968 
16:33:33 [running /etc/rc.d/raidframe]    6096  83480 
16:33:35 [running /etc/rc.d/DISKS]    6096  83480 
16:33:37 [running /etc/rc.d/swap1]    6096  83480 
swapctl: adding /dev/wd0b as swap device at priority 0
16:33:39 [running /etc/rc.d/fsck]    5704  83928 
Starting file system checks:
16:33:40 [running /etc/rc.d/mountcritlocal]    6112  83456 
[NOTE: Optional file system /var is not present]
16:33:44 [running /etc/rc.d/random_seed]    6256  83296 
Loaded entropy from /var/db/entropy-file.
16:33:46 [running /etc/rc.d/bootconf.sh]    6336  83144 
[NOTE: Output from /etc/rc.d/bootconf.sh is not logged]
16:33:48 [running /etc/rc.d/ttys]    6032  83512 
Setting tty flags.
16:33:52 [running /etc/rc.d/pf_boot]    5976  83536 
16:33:54 [running /etc/rc.d/ipsec]    5976  83536 
16:33:55 [running /etc/rc.d/ipfilter]    6416  83032 
16:33:57 [running /etc/rc.d/sysctl]    5976  83536 
Setting sysctl variables:
ddb.onpanic: 1 -> 0
16:33:59 [running /etc/rc.d/network]    5984  83528 
Starting network.
Hostname: aquila
IPv6 mode: host
Configuring network interfaces: le0.
Adding interface aliases:.
add net default: gateway 192.168.0.254
Waiting for DAD completion for statically configured addresses...
16:34:08 [running /etc/rc.d/wpa_supplicant]    6168  83224 
16:34:10 [running /etc/rc.d/dhclient]    6168  83224 
16:34:11 [running /etc/rc.d/dhcpcd]    6200  83192 
16:34:13 [running /etc/rc.d/ldpd]    6576  82752 
16:34:15 [running /etc/rc.d/npf]    6168  83224 
16:34:17 [running /etc/rc.d/pf]    6168  83224 
16:34:18 [running /etc/rc.d/route6d]    6168  83224 
16:34:20 [running /etc/rc.d/routed]    6168  83224 
16:34:22 [running /etc/rc.d/rtsold]    6168  83224 
16:34:23 [running /etc/rc.d/staticroute]    6040  83352 
16:34:25 [running /etc/rc.d/NETWORKING]    6168  83224 
16:34:27 [running /etc/rc.d/mountcritremote]    6576  82752 
[NOTE: Optional file system /usr is not present]
16:34:29 [running /etc/rc.d/sysdb]    6168  83224 
Building databases: dev, utmp, utmpx.
16:34:36 [running /etc/rc.d/newsyslog]    6264  81800 
16:34:37 [running /etc/rc.d/wscons]    6680  81320 
16:34:39 [running /etc/rc.d/syslogd]    6272  81792 
Starting syslogd.
16:34:45 [running /etc/rc.d/ppp]    8808  79072 
16:34:47 [running /etc/rc.d/named]    8400  79544 
16:34:49 [running /etc/rc.d/rtclocaltime]    8336  79608 
16:34:50 [running /etc/rc.d/ntpdate]    8400  79544 
16:34:52 [running /etc/rc.d/rpcbind]    8432  79496 
16:34:54 [running /etc/rc.d/ypserv]    8400  79528 
16:34:55 [running /etc/rc.d/ypbind]    8808  79056 
16:34:57 [running /etc/rc.d/yppasswdd]    8400  79528 
16:34:59 [running /etc/rc.d/mountall]    8400  79528 
Mounting all file systems...
16:35:01 [running /etc/rc.d/perusertmp]    8400  79520 
16:35:03 [running /etc/rc.d/cleartmp]    8736  79120 
Clearing temporary files.
16:35:05 [running /etc/rc.d/xfs]    8448  79408 
16:35:07 [running /etc/rc.d/accounting]    8448  79408 
16:35:08 [running /etc/rc.d/amd]    8856  78936 
16:35:10 [running /etc/rc.d/dmesg]    8856  78936 
16:35:12 [running /etc/rc.d/fccache]    8880  78912 
Updating fontconfig cache: done.
16:35:21 [running /etc/rc.d/veriexec]    9480  78080 
16:35:22 [running /etc/rc.d/ldconfig]    9888  77608 
Creating a.out runtime link editor directory cache.
16:35:29 [running /etc/rc.d/quota]   12160  75168 
Checking quotas: done.
16:35:31 [running /etc/rc.d/mountd]   12680  74584 
16:35:33 [running /etc/rc.d/nfsd]   12272  75056 
16:35:35 [running /etc/rc.d/nfslocking]   12272  75056 
16:35:37 [running /etc/rc.d/pwcheck]   12672  74592 
16:35:39 [running /etc/rc.d/gpio]   12584  74680 
16:35:40 [running /etc/rc.d/ipnat]   12584  74672 
16:35:42 [running /etc/rc.d/securelevel]   12272  75048 
Setting securelevel: kern.securelevel: 0 -> 1
16:35:44 [running /etc/rc.d/swap2]   12680  74576 
16:35:46 [running /etc/rc.d/virecover]   12680  74576 
Starting virecover.
16:35:49 [running /etc/rc.d/altqd]   12280  75032 
16:35:50 [running /etc/rc.d/ifwatchd]   12280  75032 
16:35:52 [running /etc/rc.d/isdnd]   12280  75032 
16:35:53 [running /etc/rc.d/ipfs]   12688  74560 
16:35:55 [running /etc/rc.d/ipmon]   12688  74560 
16:35:57 [running /etc/rc.d/kdc]   12128  75184 
16:35:59 [running /etc/rc.d/pflogd]   12688  74560 
16:36:00 [running /etc/rc.d/racoon]   12688  74560 
16:36:02 [running /etc/rc.d/savecore]   12672  74576 
Checking for core dump...
savecore: /dev/rwd1b: Device not configured
16:36:05 [running /etc/rc.d/SERVERS]   12352  74952 
16:36:06 [running /etc/rc.d/DAEMON]   12352  74952 
16:36:08 [running /etc/rc.d/apmd]   12696  74544 
16:36:09 [running /etc/rc.d/bluetooth]   12576  74696 
16:36:11 [running /etc/rc.d/bootparams]   12760  74480 
16:36:13 [running /etc/rc.d/devpubd]   12760  74480 
16:36:14 [running /etc/rc.d/dhcpd]   12352  74952 
16:36:16 [running /etc/rc.d/dhcrelay]   12760  74480 
16:36:18 [running /etc/rc.d/ftp_proxy]   12352  74952 
16:36:20 [running /etc/rc.d/irdaattach]   12352  74952 
16:36:21 [running /etc/rc.d/local]   12760  74480 
Starting local daemons:.
16:36:24 [running /etc/rc.d/lpd]   12808  74368 
16:36:25 [running /etc/rc.d/makemandb]   12400  74840 
16:36:27 [running /etc/rc.d/mopd]   12296  74944 
16:36:29 [running /etc/rc.d/motd]   12400  74840 
Updating motd.
16:36:31 [running /etc/rc.d/mrouted]   12864  74296 
16:36:33 [running /etc/rc.d/ntpd]   12456  74768 
16:36:34 [running /etc/rc.d/powerd]   12456  74768 
16:36:36 [running /etc/rc.d/rarpd]   12864  74296 
16:36:38 [running /etc/rc.d/rbootd]   12456  74768 
16:36:40 [running /etc/rc.d/rtadvd]   12312  74912 
16:36:41 [running /etc/rc.d/rwho]   12456  74768 
16:36:43 [running /etc/rc.d/screenblank]   12864  74296 
16:36:44 [running /etc/rc.d/timed]   12864  74296 
16:36:46 [running /etc/rc.d/tpctl]   12432  74792 
16:36:48 [running /etc/rc.d/LOGIN]   12456  74768 
16:36:50 [running /etc/rc.d/xdm]   12864  74296 
16:36:51 [running /etc/rc.d/wsmoused]   12640  74520 
16:36:53 [running /etc/rc.d/sshd]   12304  74920 
16:36:55 [running /etc/rc.d/raidframeparity]   12456  74768 
16:36:57 [running /etc/rc.d/postfix]   12456  74768 
16:37:42 [running /etc/rc.d/ndbootd]   20600  65912 
16:37:45 [running /etc/rc.d/moused]   22912  63368 
16:37:47 [running /etc/rc.d/mixerctl]   22880  63400 
16:37:49 [running /etc/rc.d/mdnsd]   23088  63192 
16:37:50 [running /etc/rc.d/isibootd]   23040  63240 
16:37:52 [running /etc/rc.d/iscsi_target]   22680  63664 
16:37:54 [running /etc/rc.d/inetd]   22680  63664 
Starting inetd.
16:37:56 [running /etc/rc.d/identd]   23192  63096 
16:37:58 [running /etc/rc.d/httpd]   23600  62624 
16:37:59 [running /etc/rc.d/hostapd]   23184  63040 
16:38:01 [running /etc/rc.d/ftpd]   23192  63096 
16:38:03 [running /etc/rc.d/envsys]   23520  62704 
16:38:04 [running /etc/rc.d/cron]   23344  62880 
Starting cron.
[/etc/rc finished at Sun Jan 25 16:38:06 CET 2015]
[/etc/rc exiting with status 0]
---8<---


There are no individual scripts which take longer, but all scripts take
longer. The runtime is at least doubled for every single script! So there
must be a general problem.
Also the amount of allocated memory is much higher: 23 MB instead 16 MB.

I don't think that it is caused by the kernel, because I remember I have
seen the same effect with a 6.1.5 kernel running on 7.0 userland.

-- 
Frank Wille