Port-amiga archive
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index][Old Index]
Re: 7.0 slow multiuser boot
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.
--
Frank Wille
Home |
Main Index |
Thread Index |
Old Index