From owner-freebsd-current@FreeBSD.ORG Tue Apr 13 23:54:18 2004 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 4170C16A4CE for ; Tue, 13 Apr 2004 23:54:18 -0700 (PDT) Received: from tx2.oucs.ox.ac.uk (tx2.oucs.ox.ac.uk [163.1.2.163]) by mx1.FreeBSD.org (Postfix) with ESMTP id 6523943D45 for ; Tue, 13 Apr 2004 23:54:17 -0700 (PDT) (envelope-from colin.percival@wadham.ox.ac.uk) Received: from scan2.oucs.ox.ac.uk ([163.1.2.162] helo=localhost) by tx2.oucs.ox.ac.uk with esmtp (Exim 4.24) id 1BDeHo-0008N9-KP for current@freebsd.org; Wed, 14 Apr 2004 07:54:16 +0100 Received: from rx2.oucs.ox.ac.uk ([163.1.2.161]) by localhost (scan2.oucs.ox.ac.uk [163.1.2.162]) (amavisd-new, port 25) with ESMTP id 32103-01 for ; Wed, 14 Apr 2004 07:54:15 +0100 (BST) Received: from gateway.wadham.ox.ac.uk ([163.1.161.253]) by rx2.oucs.ox.ac.uk with smtp (Exim 4.24) id 1BDeHl-0008MP-81 for current@freebsd.org; Wed, 14 Apr 2004 07:54:13 +0100 Received: (qmail 18645 invoked by uid 1004); 14 Apr 2004 06:54:13 -0000 Received: from colin.percival@wadham.ox.ac.uk by gateway by uid 71 with qmail-scanner-1.20 (clamscan: 0.67. sweep: 2.18/3.79. Clear:RC:1(163.1.161.131):. Processed in 0.604294 secs); 14 Apr 2004 06:54:13 -0000 Received: from dhcp1131.wadham.ox.ac.uk (HELO piii600.wadham.ox.ac.uk) (163.1.161.131) by gateway.wadham.ox.ac.uk with SMTP; 14 Apr 2004 06:54:12 -0000 Message-Id: <6.0.1.1.1.20040414065121.039cde20@imap.sfu.ca> X-Sender: cperciva@imap.sfu.ca (Unverified) X-Mailer: QUALCOMM Windows Eudora Version 6.0.1.1 Date: Wed, 14 Apr 2004 07:54:11 +0100 To: Peter Jeremy From: Colin Percival In-Reply-To: <20040413200013.GC53327@cirb503493.alcatel.com.au> References: <11095.1081621779@critter.freebsd.dk> <407B1EBC.6050405@freebsd.org> <407B234D.7070209@kientzle.com> <20040413160331.GM6308@numachi.com> <20040413200013.GC53327@cirb503493.alcatel.com.au> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" cc: current@freebsd.org Subject: Re: Optimizing RCng execution speed ? X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 14 Apr 2004 06:54:18 -0000 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