Port-amiga archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
Re: 7.0 slow multiuser boot
On 25 January 2015 at 16:39, Frank Wille <frank%phoenix.owl.de@localhost> wrote:
> On Sun, 25 Jan 2015 08:40:44 +0000 (UTC)
> mlelstv%serpens.de@localhost (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 :/
Home |
Main Index |
Thread Index |
Old Index