Re: 7.0 slow multiuser boot

On 25 January 2015 at 16:39, Frank Wille <[email protected]> wrote:
> 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.

Did you mean 7.0 kernel and 6.1.5 userland? Do you have the numbers
for the same boot for that for direct comparison?

Was this a 4.8 or 4.5 compiled 7.0? If it was 4.8 would it be possible
to get 4.5 numbers?

How much memory was in the machine? Could it be the 16->23MB memory
usage is pushing it into paging?

Apologies if I seem like I'm just suggesting you do even more work,
but I don't have a usable m68k box available... (I have a nice TT030
but in storage quite some way away :/