Re: 7.0 slow multiuser boot

On Thu, 5 Feb 2015 13:56:24 +0000
David Brownlee <[email protected]> wrote:

> > First NetBSD 6.1.5. Takes 2 minutes and 39 seconds:
> > [...]
> >
> > Now NetBSD 7.0beta (from last week). Takes 4 minutes and 51 seconds.
> > [...]
> >
> > 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?

No. I started the old 6.1.5 kernel with a recent userland.
BTW, I just realized userland is not 7.0beta, but 7.99.4.


> Do you have the numbers
> for the same boot for that for direct comparison?

Sure. Here are the numbers for a 6.1.5 kernel running 7.99.4 userland:

[/etc/rc starting at Fri Feb  6 16:17:21 CET 2015]
16:17:23 [running rcorder]    4720  82848 
16:17:26 [running /etc/rc.d/wdogctl]    5776  81744 
16:17:27 [running /etc/rc.d/fsck_root]    5608  81936 
Starting root file system check:
/dev/rwd1a: file system is clean; not checking
16:17:30 [running /etc/rc.d/root]    6048  81360 
16:17:32 [running /etc/rc.d/ccd]    5928  81512 
16:17:34 [running /etc/rc.d/rndctl]    5704  81768 
16:17:36 [running /etc/rc.d/cgd]    5704  81768 
[NOTE: Output from /etc/rc.d/cgd is not logged]
16:17:38 [running /etc/rc.d/lvm]    6112  81296 
16:17:40 [running /etc/rc.d/raidframe]    6144  81232 
16:17:41 [running /etc/rc.d/DISKS]    6144  81264 
16:17:43 [running /etc/rc.d/swap1]    6200  81176 
swapctl: adding /dev/wd0b as swap device at priority 0
16:17:45 [running /etc/rc.d/fsck]    5720  81744 
Starting file system checks:
16:17:47 [running /etc/rc.d/mountcritlocal]    6128  81272 
[NOTE: Optional file system /var is not present]
16:17:50 [running /etc/rc.d/random_seed]    6272  81104 
Loaded entropy from /var/db/entropy-file.
16:17:53 [running /etc/rc.d/bootconf.sh]    5944  81424 
[NOTE: Output from /etc/rc.d/bootconf.sh is not logged]
16:17:55 [running /etc/rc.d/ttys]    6376  80928 
Setting tty flags.
16:17:58 [running /etc/rc.d/pf_boot]    6584  80648 
16:18:00 [running /etc/rc.d/ipsec]    6400  80864 
16:18:02 [running /etc/rc.d/ipfilter]    6088  81208 
16:18:03 [running /etc/rc.d/sysctl]    6488  80744 
Setting sysctl variables:
ddb.onpanic: 1 -> 0
16:18:05 [running /etc/rc.d/network]    6712  80520 
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:18:15 [running /etc/rc.d/wpa_supplicant]    6512  80672 
16:18:16 [running /etc/rc.d/dhclient]    6592  80560 
16:18:18 [running /etc/rc.d/dhcpcd]    6184  81032 
16:18:20 [running /etc/rc.d/ldpd]    6184  81032 
16:18:22 [running /etc/rc.d/npf]    6032  81184 
16:18:23 [running /etc/rc.d/pf]    6592  80560 
16:18:25 [running /etc/rc.d/route6d]    6592  80560 
16:18:27 [running /etc/rc.d/routed]    6592  80560 
16:18:29 [running /etc/rc.d/rtsold]    6592  80560 
16:18:30 [running /etc/rc.d/staticroute]    6624  80528 
16:18:32 [running /etc/rc.d/NETWORKING]    6592  80560 
16:18:34 [running /etc/rc.d/mountcritremote]    6624  80528 
[NOTE: Optional file system /usr is not present]
16:18:36 [running /etc/rc.d/sysdb]    6088  81128 
Building databases: dev, utmp, utmpx.
16:18:43 [running /etc/rc.d/newsyslog]    6824  79024 
16:18:44 [running /etc/rc.d/wscons]    6696  79152 
16:18:46 [running /etc/rc.d/syslogd]    6528  79320 
Starting syslogd.
16:18:52 [running /etc/rc.d/ppp]    8824  76896 
16:18:54 [running /etc/rc.d/named]    8576  77144 
16:18:56 [running /etc/rc.d/rtclocaltime]    8824  76896 
16:18:58 [running /etc/rc.d/ntpdate]    8824  76896 
16:18:59 [running /etc/rc.d/rpcbind]    8416  77368 
16:19:01 [running /etc/rc.d/ypserv]    8824  76896 
16:19:03 [running /etc/rc.d/ypbind]    8824  76896 
16:19:05 [running /etc/rc.d/yppasswdd]    8640  77112 
16:19:06 [running /etc/rc.d/mountall]    8416  77368 
Mounting all file systems...
16:19:09 [running /etc/rc.d/perusertmp]    8824  76896 
16:19:11 [running /etc/rc.d/cleartmp]    8416  77368 
Clearing temporary files.
16:19:13 [running /etc/rc.d/xfs]    8872  76784 
16:19:15 [running /etc/rc.d/accounting]    8872  76784 
16:19:16 [running /etc/rc.d/amd]    8680  76960 
16:19:18 [running /etc/rc.d/dmesg]    8464  77240 
16:19:21 [running /etc/rc.d/fccache]    8896  76744 
Updating fontconfig cache: done.
16:19:29 [running /etc/rc.d/veriexec]    9904  75440 
16:19:31 [running /etc/rc.d/ldconfig]    9904  75440 
Creating a.out runtime link editor directory cache.
16:19:37 [running /etc/rc.d/quota]   12064  73104 
Checking quotas: done.
16:19:40 [running /etc/rc.d/mountd]   12696  72408 
16:19:42 [running /etc/rc.d/nfsd]   12696  72408 
16:19:43 [running /etc/rc.d/nfslocking]   12464  72672 
16:19:45 [running /etc/rc.d/pwcheck]   12280  72888 
16:19:47 [running /etc/rc.d/gpio]   12144  73024 
16:19:49 [running /etc/rc.d/ipnat]   12696  72408 
16:19:51 [running /etc/rc.d/securelevel]   12288  72880 
Setting securelevel: kern.securelevel: 0 -> 1
16:19:53 [running /etc/rc.d/swap2]   12696  72408 
16:19:55 [running /etc/rc.d/virecover]   12696  72408 
Starting virecover.
16:19:57 [running /etc/rc.d/altqd]   12296  72872 
16:19:59 [running /etc/rc.d/ifwatchd]   12656  72448 
16:20:01 [running /etc/rc.d/isdnd]   12672  72432 
16:20:03 [running /etc/rc.d/ipfs]   12296  72872 
16:20:05 [running /etc/rc.d/ipmon]   12296  72872 
16:20:06 [running /etc/rc.d/kdc]   12704  72400 
16:20:08 [running /etc/rc.d/pflogd]   12704  72400 
16:20:10 [running /etc/rc.d/racoon]   12296  72872 
16:20:12 [running /etc/rc.d/savecore]   12296  72872 
Checking for core dump...
savecore: /dev/rwd1b: Device not configured
16:20:14 [running /etc/rc.d/SERVERS]   12368  72792 
16:20:16 [running /etc/rc.d/DAEMON]   12776  72320 
16:20:17 [running /etc/rc.d/apmd]   12776  72320 
16:20:19 [running /etc/rc.d/bluetooth]   12368  72792 
16:20:21 [running /etc/rc.d/bootparams]   12776  72320 
16:20:22 [running /etc/rc.d/devpubd]   12776  72320 
16:20:24 [running /etc/rc.d/dhcpd]   12776  72320 
16:20:26 [running /etc/rc.d/dhcrelay]   12776  72320 
16:20:28 [running /etc/rc.d/ftp_proxy]   12368  72792 
16:20:30 [running /etc/rc.d/irdaattach]   12368  72792 
16:20:31 [running /etc/rc.d/local]   12776  72320 
Starting local daemons:.
16:20:34 [running /etc/rc.d/lpd]   12824  72200 
16:20:35 [running /etc/rc.d/makemandb]   12824  72200 
16:20:37 [running /etc/rc.d/mopd]   12416  72672 
16:20:39 [running /etc/rc.d/motd]   12824  72200 
Updating motd.
16:20:42 [running /etc/rc.d/mrouted]   12496  72592 
16:20:43 [running /etc/rc.d/ntpd]   12688  72336 
16:20:45 [running /etc/rc.d/powerd]   12880  72144 
16:20:47 [running /etc/rc.d/rarpd]   12496  72592 
16:20:49 [running /etc/rc.d/rbootd]   12496  72592 
16:20:50 [running /etc/rc.d/rtadvd]   12904  72120 
16:20:52 [running /etc/rc.d/rwho]   12904  72120 
16:20:54 [running /etc/rc.d/screenblank]   12496  72592 
16:20:55 [running /etc/rc.d/timed]   12856  72168 
16:20:57 [running /etc/rc.d/tpctl]   12904  72120 
16:20:59 [running /etc/rc.d/LOGIN]   12496  72592 
16:21:01 [running /etc/rc.d/xdm]   12880  72144 
16:21:02 [running /etc/rc.d/wsmoused]   12904  72120 
16:21:04 [running /etc/rc.d/sshd]   12760  72264 
16:21:06 [running /etc/rc.d/raidframeparity]   12496  72592 
16:21:08 [running /etc/rc.d/postfix]   12904  72120 
16:21:54 [running /etc/rc.d/ndbootd]   21232  62920 
16:21:57 [running /etc/rc.d/moused]   22704  61496 
16:21:58 [running /etc/rc.d/mixerctl]   23120  61008 
16:22:00 [running /etc/rc.d/mdnsd]   23120  61008 
16:22:02 [running /etc/rc.d/isibootd]   23120  61008 
16:22:04 [running /etc/rc.d/iscsi_target]   23120  61008 
16:22:05 [running /etc/rc.d/inetd]   22632  61560 
Starting inetd.
16:22:08 [running /etc/rc.d/identd]   23232  60928 
16:22:10 [running /etc/rc.d/httpd]   23456  60672 
16:22:11 [running /etc/rc.d/hostapd]   23600  60488 
16:22:13 [running /etc/rc.d/ftpd]   23640  60448 
16:22:15 [running /etc/rc.d/envsys]   23672  60384 
16:22:17 [running /etc/rc.d/cron]   23640  60416 
Starting cron.
[/etc/rc finished at Fri Feb  6 16:22:18 CET 2015]


Nearly 5 minutes. The numbers are equally bad with a 6.1.5 kernel running
7.99.4 userland as with a 7.0beta kernel running 7.99.4 userland.

Also 23MB are allocated again (which was expected).


> Was this a 4.8 or 4.5 compiled 7.0?

4.5


> How much memory was in the machine?

96 MB Fast RAM and 2 MB Chip RAM.


> Could it be the 16->23MB memory usage is pushing it into paging?

I doubt that.


> 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 :/

A 68030 system would be completely unusable with a V7 userland. I tried
it with my A1200 68030/42MHz and it took more than 15 minutes to boot.


There is something which I noticed during the last tests, which might be
an important hint:

When you press CTRL-t during multiuser boot from time to time, then you
see the currently executed command. With 6.1.5 userland everything is
normal. But with 7.99.4 (and most likely 7.0 as well) you see very frequently
"cmd: sleep [nanosleep]" !

Seems that it is now sleeping half of the boot process. But why?

-- 
Frank Wille