Re: Optimizing RCng execution speed ?

From: Colin Percival <colin.percival_at_wadham.ox.ac.uk>
Date: Wed, 14 Apr 2004 07:54:11 +0100
At 21:00 13/04/2004, Peter Jeremy wrote:
>The time-consuming bits are starting a new shell and sourcing the
>config files.

  Not quite.  The main configuration files don't get re-sourced
each time -- rc.subr uses an "_rc_conf_loaded" variable to avoid
this.  However, rc.subr itself gets re-sourced, which seems quite
unnecessary; removing this (via an _rc_subr_loaded variable) gives
a roughly 20% speedup.

>If someone wants to have a look at this,
>the place to start is to profile the complete system during startup
>and see where the time is going.

  On my 5.2.1 system (with the mentioned don't-reload-rc.subr patch):
Starting RC scripts:                    kern.cp_time: 1 0 44 2 53
RC done: /etc/rc.d/initdiskless:        kern.cp_time: 3 0 67 2 60
RC done: /etc/rc.d/rcconf.sh:           kern.cp_time: 3 0 70 2 61
RC done: /etc/rc.d/initrandom:  kern.cp_time: 3 0 125 2 66
RC done: /etc/rc.d/dumpon:              kern.cp_time: 3 0 127 2 66
RC done: /etc/rc.d/vinum:               kern.cp_time: 4 0 128 2 66
RC done: /etc/rc.d/gbde:                kern.cp_time: 4 0 132 2 66
RC done: /etc/rc.d/ccd:                 kern.cp_time: 4 0 134 2 66
RC done: /etc/rc.d/swap1:               kern.cp_time: 5 0 138 2 67
RC done: /etc/rc.d/early.sh:            kern.cp_time: 5 0 140 2 67
RC done: /etc/rc.d/fsck:                kern.cp_time: 7 0 226 2 115
RC done: /etc/rc.d/root:                kern.cp_time: 8 0 238 2 122
RC done: /etc/rc.d/sppp:                kern.cp_time: 8 0 240 2 122
RC done: /etc/rc.d/serial:              kern.cp_time: 8 0 242 2 122
RC done: /etc/rc.d/mountcritlocal:      kern.cp_time: 9 0 300 2 241
RC done: /etc/rc.d/atm1:                kern.cp_time: 9 0 301 2 242
RC done: /etc/rc.d/pccard:              kern.cp_time: 9 0 302 2 243
RC done: /etc/rc.d/kldxref:             kern.cp_time: 9 0 303 2 244
RC done: /etc/rc.d/ipsec:               kern.cp_time: 9 0 304 2 245
RC done: /etc/rc.d/hostname:            kern.cp_time: 9 0 307 2 250
RC done: /etc/rc.d/diskless:            kern.cp_time: 9 0 308 2 251
RC done: /etc/rc.d/cleanvar:            kern.cp_time: 9 0 315 2 278
RC done: /etc/rc.d/random:              kern.cp_time: 11 0 323 2 298
RC done: /etc/rc.d/addswap:             kern.cp_time: 11 0 324 2 299
RC done: /etc/rc.d/sysctl:              kern.cp_time: 11 0 326 2 301
RC done: /etc/rc.d/adjkerntz:           kern.cp_time: 12 0 327 2 303
RC done: /etc/rc.d/ipmon:               kern.cp_time: 13 0 327 2 304
RC done: /etc/rc.d/ipfilter:            kern.cp_time: 14 0 328 2 306
RC done: /etc/rc.d/ipnat:               kern.cp_time: 14 0 329 2 307
RC done: /etc/rc.d/ipfs:                kern.cp_time: 14 0 330 2 308
RC done: /etc/rc.d/netif:               kern.cp_time: 14 0 335 2 333
RC done: /etc/rc.d/isdnd:               kern.cp_time: 14 0 336 2 334
RC done: /etc/rc.d/ip6addrctl:  kern.cp_time: 15 0 337 2 336
RC done: /etc/rc.d/dhclient:            kern.cp_time: 16 0 338 2 338
RC done: /etc/rc.d/atm2:                kern.cp_time: 16 0 339 2 339
RC done: /etc/rc.d/ppp-user:            kern.cp_time: 16 0 341 2 349
RC done: /etc/rc.d/atm3:                kern.cp_time: 17 0 341 2 350
RC done: /etc/rc.d/routing:             kern.cp_time: 19 0 341 2 354
RC done: /etc/rc.d/ipfw:                kern.cp_time: 23 0 343 2 370
RC done: /etc/rc.d/routed:              kern.cp_time: 23 0 344 2 371
RC done: /etc/rc.d/mrouted:             kern.cp_time: 23 0 345 2 372
RC done: /etc/rc.d/ip6fw:               kern.cp_time: 23 0 347 2 374
RC done: /etc/rc.d/network_ipv6:        kern.cp_time: 24 0 347 2 375
RC done: /etc/rc.d/route6d:             kern.cp_time: 24 0 348 2 376
RC done: /etc/rc.d/mroute6d:            kern.cp_time: 24 0 349 2 377
RC done: /etc/rc.d/NETWORKING:  kern.cp_time: 24 0 350 2 378
RC done: /etc/rc.d/pppoed:              kern.cp_time: 24 0 351 2 379
RC done: /etc/rc.d/kerberos:            kern.cp_time: 24 0 352 2 380
RC done: /etc/rc.d/devd:                kern.cp_time: 24 0 354 2 382
RC done: /etc/rc.d/mountcritremote:     kern.cp_time: 24 0 359 2 387
RC done: /etc/rc.d/kadmind:             kern.cp_time: 24 0 359 2 387
RC done: /etc/rc.d/ttys:                kern.cp_time: 24 0 362 2 396
RC done: /etc/rc.d/quota:               kern.cp_time: 24 0 363 2 397
RC done: /etc/rc.d/nfsserver:           kern.cp_time: 24 0 364 2 398
RC done: /etc/rc.d/motd:                kern.cp_time: 26 0 367 2 421
RC done: /etc/rc.d/lomac:               kern.cp_time: 26 0 368 2 422
RC done: /etc/rc.d/ldconfig:            kern.cp_time: 26 0 372 2 446
RC done: /etc/rc.d/kpasswdd:            kern.cp_time: 26 0 373 2 447
RC done: /etc/rc.d/dmesg:               kern.cp_time: 26 0 376 2 450
RC done: /etc/rc.d/cleartmp:            kern.cp_time: 26 0 379 2 463
RC done: /etc/rc.d/accounting:  kern.cp_time: 26 0 380 2 464
RC done: /etc/rc.d/virecover:           kern.cp_time: 26 0 383 2 479
RC done: /etc/rc.d/syslogd:             kern.cp_time: 26 0 393 3 696
RC done: /etc/rc.d/savecore:            kern.cp_time: 26 0 394 3 697
RC done: /etc/rc.d/pwcheck:             kern.cp_time: 27 0 394 3 698
RC done: /etc/rc.d/ntpdate:             kern.cp_time: 28 0 394 3 699
RC done: /etc/rc.d/SERVERS:             kern.cp_time: 28 0 395 3 700
RC done: /etc/rc.d/named:               kern.cp_time: 28 0 396 3 701
RC done: /etc/rc.d/ipxrouted:           kern.cp_time: 28 0 397 3 702
RC done: /etc/rc.d/rpcbind:             kern.cp_time: 29 0 398 3 704
RC done: /etc/rc.d/nisdomain:           kern.cp_time: 29 0 399 3 705
RC done: /etc/rc.d/nfsclient:           kern.cp_time: 29 0 400 3 706
RC done: /etc/rc.d/mountd:              kern.cp_time: 29 0 401 3 707
RC done: /etc/rc.d/ypxfrd:              kern.cp_time: 29 0 402 3 708
RC done: /etc/rc.d/ypserv:              kern.cp_time: 29 0 403 3 709
RC done: /etc/rc.d/nfsd:                kern.cp_time: 29 0 404 3 710
RC done: /etc/rc.d/ypupdated:           kern.cp_time: 29 0 404 4 711
RC done: /etc/rc.d/ypbind:              kern.cp_time: 30 0 404 4 712
RC done: /etc/rc.d/nfslocking:  kern.cp_time: 30 0 405 4 713
RC done: /etc/rc.d/ypset:               kern.cp_time: 31 0 405 4 714
RC done: /etc/rc.d/yppasswdd:           kern.cp_time: 31 0 406 4 715
RC done: /etc/rc.d/keyserv:             kern.cp_time: 31 0 407 4 716
RC done: /etc/rc.d/amd:                 kern.cp_time: 31 0 408 4 717
RC done: /etc/rc.d/DAEMON:              kern.cp_time: 31 0 409 4 718
RC done: /etc/rc.d/watchdogd:           kern.cp_time: 31 0 410 4 719
RC done: /etc/rc.d/usbd:                kern.cp_time: 31 0 411 4 720
RC done: /etc/rc.d/timed:               kern.cp_time: 31 0 412 4 721
RC done: /etc/rc.d/rwho:                kern.cp_time: 32 0 412 4 722
RC done: /etc/rc.d/rtadvd:              kern.cp_time: 32 0 413 4 723
RC done: /etc/rc.d/rarpd:               kern.cp_time: 33 0 414 4 725
RC done: /etc/rc.d/ntpd:                kern.cp_time: 33 0 415 4 726
RC done: /etc/rc.d/moused:              kern.cp_time: 33 0 416 4 727
RC done: /etc/rc.d/lpd:                 kern.cp_time: 33 0 417 4 728
RC done: /etc/rc.d/local:               kern.cp_time: 34 0 417 4 729
RC done: /etc/rc.d/bootparams:  kern.cp_time: 35 0 417 4 730
RC done: /etc/rc.d/apm:                 kern.cp_time: 35 0 419 4 732
RC done: /etc/rc.d/apmd:                kern.cp_time: 35 0 420 4 733
RC done: /etc/rc.d/LOGIN:               kern.cp_time: 35 0 420 4 733
RC done: /etc/rc.d/syscons:             kern.cp_time: 35 0 422 4 741
RC done: /etc/rc.d/sshd:                kern.cp_time: 35 0 431 4 806
RC done: /etc/rc.d/sendmail:            kern.cp_time: 36 0 432 4 808
RC done: /etc/rc.d/pcvt:                kern.cp_time: 39 0 433 4 808
RC done: /etc/rc.d/othermta:            kern.cp_time: 40 0 434 4 808
RC done: /etc/rc.d/msgs:                kern.cp_time: 43 0 434 4 809
RC done: /etc/rc.d/jail:                kern.cp_time: 44 0 435 4 809
RC done: /etc/rc.d/inetd:               kern.cp_time: 46 0 435 4 809
RC done: /etc/rc.d/devfs:               kern.cp_time: 50 0 438 4 810
RC done: /etc/rc.d/cron:                kern.cp_time: 57 0 440 4 813
RC done: /etc/rc.d/archdep:             kern.cp_time: 59 0 442 4 813
RC done: /etc/rc.d/bgfsck:              kern.cp_time: 61 0 444 4 813
RC done: /etc/rc.d/abi:                 kern.cp_time: 64 0 447 4 813
RC done: /etc/rc.d/localpkg:            kern.cp_time: 70 0 451 5 816
RC done: /etc/rc.d/netoptions:  kern.cp_time: 71 0 452 5 816
RC done: /etc/rc.d/securelevel:         kern.cp_time: 71 0 455 5 819
RC scripts done:                        kern.cp_time: 71 0 455 5 819

Out of the total 4.88 seconds the major consumers are:

syslogd         0.89 s
mountcritlocal          0.70 s
fsck                    0.53 s
sshd                    0.29 s
initrandom              0.24 s
cleanvar                0.13 s
netif                   0.12 s
motd                    0.11 s
ldconfig                0.11 s

Also note that the 35 conecutive scripts {savecore ... LOGIN} which
do nothing take under 0.01 seconds each (which is mostly overhead
from reading the cp_time statistics); thus, any optimization should
probably be targetted at scripts which actually do something. :-)

Colin Percival
Received on Tue Apr 13 2004 - 21:54:18 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:37:51 UTC