debian/etch-booting-20050901/report.html

   1 <html>
   2 <body>
   3 <h1>Speeding up the debian/etch boot, a short report</h1>
   4
   5 <p>The test machine in question is a COMPAQ ProLiant DL360 with 2CPU
   6 800/133 MHz, 1.5GiB RAM and 2x18GiB SCSI disks in HW-RAID.
   7
   8 <p>Installed etch using a sarge netinst CD and pointing APT to
   9 'testing'.  Install the desktop task.  The kernel is 2.4.27-2-386.
  10
  11 <p>Installed the bootchart package from
  12 http://www.minet.uni-jena.de/~joergs/bootchart/bootchart_0.8-2_all.deb
  13
  14 <p>Booted grub after adding 'init=/sbin/bootchartd' to the kernel
  15 arguments.  Archive the resulting /var/log/bootchart.tgz as
  16 <a href="2005-08-01T18:07-bootchart.png">2005-08-01T18:07-bootchart.tgz</a>.  This boot took 45 seconds.
  17 S20modutils is the largest single contributor and used about 13
  18 seconds of this period.
  19
  20 <p>Installed kernel kernel-image-2.4.27-2-686-smp and rebooted with
  21 bootchart, to see if this make a difference.  The stats were saved as
  22 <a href="2005-08-01T18:16-bootchart.png">2005-08-01T18:16-bootchart.tgz</a>.
  23 This boot took 1 minute 33 seconds.  Again S20modutils is the slowest
  24 part of the boot, spending 23 seconds of it.
  25
  26 <p>Time to reorder the boot sequence according to dependencies.  Document
  27 the default boot order:
  28
  29 <pre>
  30   # ls /etc/rcS.d/
  31   README              S20module-init-tools  S36udev-mtab   S48console-screen.sh
  32   S02mountvirtfs      S20modutils           S38pppd-dns    S50hwclock.sh
  33   S04udev             S25libdevmapper1.01   S39dns-clean   S55bootmisc.sh
  34   S05bootlogd         S26lvm                S39ifupdown    S55urandom
  35   S05initrd-tools.sh  S30checkfs.sh         S40hostname.sh S70nviboot
  36   S05keymap.sh        S30procps.sh          S40hotplug     S70xfree86-common
  37   S10checkroot.sh     S35mountall.sh        S40networking  S75sudo
  38   S18hwclockfirst.sh  S36discover           S43portmap
  39   S18ifupdown-clean   S36mountvirtfs        S45mountnfs.sh
  40   # ls /etc/rc2.d/
  41   S10sysklogd  S18portmap  S20exim4  S20makedev S21nfs-common  S99gdm
  42   S11klogd     S20dbus-1   S20inetd  S20ssh     S89atd         S99rmnologin
  43   S14ppp       S20dirmngr  S20lpd    S21fam     S89cron        S99stop-bootlogd
  44   #
  45 </pre>
  46
  47 <p>Discovering that a few packages was not upgraded to from sarge to
  48 testing.  Doing a 'aptitude dist-upgrade' to get these packages
  49 upgrade: dash eject fdutils grub hotplug initrd-tools
  50 kernel-image-2.4.27-2-386 lvm2 ppp pppconfig pppoeconf psmisc usbutils
  51
  52 <p>Realises that a new boot is needed to get status for the packages in
  53 etch and not in sarge, as several of the upgraded packages have init.d
  54 scripts.
  55
  56 <p>Booted first using -686-smp kernel.  This took 1 minute 31 seconds
  57 (<a href="2005-08-01T18:31-bootchart.png">2005-08-01T18:31-bootchart.tgz</a>).
  58 Still S20modutils spending most of the time.
  59
  60 <p><a href="2005-08-01T18:36-bootchart.png"><img src="2005-08-01T18:36-bootchart.png" width="40%" align="right"></a>Next
  61 booted with the -383 kernel.  This took 46 seconds
  62 (<a href="2005-08-01T18:36-bootchart.png">2005-08-01T18:36-bootchart.tgz</a>).
  63
  64 <p>Someone claimed switching to dash instead of bash should speed up
  65 the boot process.  I decided to test it with the -386 kernel.  The
  66 default was sh->bash.  Changed this to sh->dash and rebooted.  The
  67 boot still took 46 seconds.
  68
  69 <p>Finally, I installed and executed insserv -v and saved the output
  70 (2005-08-01T18:45-insserv-1.log).  To verify that the result was
  71 stable, I ran it again and saved the output
  72 (2005-08-01T18:45-insserv-2.log).  This time
  73 rc[2345].d/S19stop-bootlogd was moved to S20stop-bootlogd.  I suspect
  74 the dependencies of stop-bootlogd are a bit strange, as this is a
  75 script expected to be executed several times in the boot process.
  76 Running insserv a third time didn't give any changes, so I did not
  77 save that output.
  78
  79 <p>Checking the resulting boot sequence seemed to make fairly good sense
  80 to me:
  81
  82 <pre>
  83   # ls /etc/rcS.d
  84   README                S03initrd-tools.sh  S08checkfs.sh  S13hotplug-net
  85   S01hostname.sh        S04keymap.sh        S09mountall.sh S13mountnfs.sh
  86   S01hwclockfirst.sh    S05checkroot.sh     S11bootmisc.sh S15console-screen.sh
  87   S01mountvirtfs        S06discover         S11dns-clean   S15nviboot
  88   S02bootlogd           S06hotplug          S11networking  S15xfree86-common
  89   S02module-init-tools  S06ifupdown-clean   S11sudo        S16hwclock.sh
  90   S02modutils           S07ifupdown         S11udev-mtab   S17ntpdate
  91   S02procps.sh          S07libdevmapper1.01 S11urandom     S43portmap
  92   S02udev               S07lvm              S12pppd-dns
  93   # ls /etc/rc2.d/
  94   S11makedev  S15nfs-common  S19klogd          S21cron     S21exim4  S21lpd
  95   S14portmap  S18rmnologin   S20stop-bootlogd  S21dbus-1   S21gdm    S21ppp
  96   S15fam      S18sysklogd    S21atd            S21dirmngr  S21inetd  S21ssh
  97   #
  98 </pre>
  99
 100 <p>Time to reboot again.  Used the 386 kernel as this was the fastest
 101 boot.  gdm came up with a login promt way before the machine was
 102 finished booting.  The network failed to start as the network modules
 103 was not loaded.  Running '/etc/init.d/discover start &&
 104 /etc/init.d/networking start' fixes this problem.  The new boot took
 105 28 seconds
 106 (<a href="2005-08-01T18:55-bootchart.png">2005-08-01T18:55-bootchart.tgz</a>).
 107
 108 <p>Tried modifying the dependencies of discover, lvm and hotplug to
 109 get the network drivers loaded properly.  Succeeded and the new boot
 110 order ended up like this:
 111
 112 <pre>
 113   # ls /etc/rcS.d/
 114   README                S05checkroot.sh    S10libdevmapper1.01
 115   S01hostname.sh        S06checkfs.sh      S10networking
 116   S01hwclockfirst.sh    S06ifupdown-clean  S10pppd-dns
 117   S01mountvirtfs        S07ifupdown        S12hotplug-net
 118   S02bootlogd           S07mountall.sh     S12mountnfs.sh
 119   S02module-init-tools  S09bootmisc.sh     S14console-screen.sh
 120   S02modutils           S09discover        S14nviboot
 121   S02procps.sh          S09dns-clean       S14xfree86-common
 122   S02udev               S09hotplug         S15hwclock.sh
 123   S03initrd-tools.sh    S09sudo            S16ntpdate
 124   S03lvm                S09udev-mtab       S43portmap
 125   S04keymap.sh          S09urandom
 126   #
 127 </pre>
 128
 129 <p>This new boot took 36 seconds (2005-08-01T19:22-bootchart.tgz), and
 130 the network started as it should.
 131
 132 <p>Tested with the -686-smp kernel as well.  This new boot with the SMP
 133 kernel took 58 seconds
 134 (<a href="2005-08-01T19:33-bootchart.png">2005-08-01T19:33-bootchart.tgz</a>) .
 135
 136 <p>It was time to test the parallel booting.  I ran 'cp
 137 /usr/share/doc/insserv/examples/rc* /etc/init.d/', and rebooted with
 138 the 386 kernel.  This time to boot took 34 seconds
 139 (<a href="2005-08-01T19:38-bootchart.png">2005-08-01T19:38-bootchart.tgz</a>).
 140 The gain was not very impressive, but it was slightly faster.
 141
 142 <p>The SMP boot on the other hand surprised me quite a bit.  The boot
 143 took 1 minute 9 seconds
 144 (<a href="2005-08-01T19:41-bootchart.png">2005-08-01T19:41-bootchart.tgz</a>),
 145 and there is a large section of the boot time unaccounted for.  From
 146 10 to 20 seconds into the boot, nothing is running but the CPU is used
 147 quite a bit.  I was so surprised I had to try again to see if this
 148 happened every time.  The new boot took the exact same amount of time
 149 (<a href="2005-08-01T19:49-bootchart.png">2005-08-01T19:49-bootchart.tgz</a>),
 150 and had the same gap in the boot process where nothing is using an
 151 increasing amount of CPU.  I suspect some kernel module must be
 152 spending the resources.
 153
 154 <p>Trying to squease more parallelism in the boot process, I adjusted
 155 the dependencies slightly to end up with this sequence:
 156
 157 <pre>
 158   # ls /etc/rcS.d/
 159   README                S03lvm               S08networking
 160   S01hostname.sh        S04checkfs.sh        S08pppd-dns
 161   S01hwclockfirst.sh    S04ifupdown-clean    S10hotplug-net
 162   S01mountvirtfs        S05ifupdown          S10mountnfs.sh
 163   S02bootlogd           S05mountall.sh       S12console-screen.sh
 164   S02keymap.sh          S07bootmisc.sh       S12hwclock.sh
 165   S02module-init-tools  S07discover          S12nviboot
 166   S02modutils           S07dns-clean         S12sudo
 167   S02procps.sh          S07hotplug           S12xfree86-common
 168   S02udev               S07udev-mtab         S13ntpdate
 169   S03checkroot.sh       S07urandom           S13portmap
 170   S03initrd-tools.sh    S08libdevmapper1.01
 171   #
 172 </pre>
 173
 174 <p>The new boot with the SMP kernel still took 1 minute 9 seconds
 175 (<a href="2005-08-01T20:08-bootchart.png">2005-08-01T20:08-bootchart.tgz</a>).
 176
 177 <p>Next, I tried to optimize the gdm startup, moving it ahead in the
 178 rc2.d sequence.  After some dependency adjustements, I ended up with
 179 this sequence:
 180
 181 <pre>
 182   # ls /etc/rc2.d/
 183   S07makedev   S12fam         S14sysklogd       S17atd     S17dirmngr  S17ppp
 184   S07rmnologin S12gdm         S15klogd          S17cron    S17exim4    S17ssh
 185   S11portmap   S12nfs-common  S16stop-bootlogd  S17dbus-1  S17lpd      S20inetd
 186   #
 187 </pre>
 188
 189 <p>This new sequence was 1 second slower for the SMP kernel.  It took
 190 1 minute 10 seconds
 191 (<a href="2005-08-01T20:35-bootchart.png">2005-08-01T20:35-bootchart.tgz</a>).
 192 I suspect the issue here are IO contention, were several processes
 193 want to read from the disk at the same time.
 194
 195 <p>Next, I tested with the 386 kernel, and this boot took 34 seconds
 196 (<a href="2005-08-01T20:38-bootchart.png">2005-08-01T20:38-bootchart.tgz</a>).
 197
 198 <h2>Testing 2.6 kernels</h2>
 199
 200 <p>To see if the results were modified by using a 2.6 kernel, I installed
 201 kernel-image-2.6.11-1-386 and kernel-image-2.6.11-1-686-smp.  I was
 202 asked how to configure irqbalance.  I selected the default (no).
 203 After installing these kernels, I booted the 386 kernel first.  This
 204 boot took 36 seconds
 205 (<a href="2005-08-01T20:55-bootchart.png">2005-08-01T20:55-bootchart.tgz</a>).
 206 This new boot included more stats in the graphs, and a few new
 207 processes (udevd, hald).
 208
 209 <p>Next, I booted the 2.6 SMP kernel, and this boot took 1 minute 6
 210 seconds
 211 (<a href="2005-08-01T20:58-bootchart.png">2005-08-01T20:58-bootchart.tgz</a>).
 212 Still almost double the time of the 2.4 kernel.
 213
 214 <h2>Speedups</h2>
 215
 216 <p>Portmap tries to start twice.  Once from rcS.d, and another from
 217 rc2.d.  It does a sleep 1 every time.  By modifying the script to exit
 218 imediately if portmap already is running, I should be able to cut down
 219 the boot time by one second.  Testing with this patch.
 220
 221 <pre>
 222 --- /etc/init.d/portmap.orig    2005-09-01 21:03:40.000000000 +0200
 223 +++ /etc/init.d/portmap 2005-09-01 21:05:40.000000000 +0200
 224 @@ -13,6 +13,11 @@
 225
 226  case "$1" in
 227      start)
 228 +       pid=`pidof portmap`
 229 +       if [ -n "$pid" ] ; then
 230 +         echo "Not starting portmap daemon.  Already running."
 231 +         exit 0
 232 +       fi
 233         echo -n "Starting portmap daemon:"
 234         echo -n " portmap"
 235         start-stop-daemon --start --quiet --oknodo --exec /sbin/portmap -- $OPTIONS
 236 </pre>
 237
 238 <p>I booted the 2.4 386 kernel, and this worked just fine.  Now gdm
 239 started imediately as the rc2.d scripts started, and the boot time is
 240 34 seconds
 241 (<a href="2005-08-01T21:09-bootchart.png">2005-08-01T21:09-bootchart.tgz</a>).
 242 The total boot time to be the same as before, which is rather strange.
 243 Anyway, the change seem sensible enough, so I submitted it to BTS as
 244 <a href="http://bugs.debian.org/326100">bug #326100</a>.
 245
 246 <p>Next, I realise that ntpdate and portmap do not really need to run
 247 in rcS.d/.  Moving them both to rc2.d and running insserv -v again, it
 248 is time to try a new boot.
 249
 250 <p>The new boot worked fine, but it still took 34 seconds to boot with
 251 the 386 kernel
 252 (<a href="2005-08-01T21:21-bootchart.png">2005-08-01T21:21-bootchart.tgz</a>).
 253
 254 <p>Time to look at readahead?  I tried with a trivial implementation,
 255 using 'nice cat <files> &'.  The files were all scripts in /etc/rcS.d/
 256 /etc/rc2.d/ and all .o files under /lib/modules/.  This had no effect
 257 whatsoever.  The boot still took 34 seconds
 258 (<a href="2005-08-01T21:45-bootchart.png">2005-08-01T21:45-bootchart.tgz</a>).
 259
 260 <p>It takes almost 10 seconds to start gdm.  Why is this?  Will it
 261 help to move to xdm or kdm?  Testing xdm first, as it is supposed to
 262 be the trivial implementation.  Copied the dependencies from gdm, ran
 263 insserv, and booted the 386 2.4 kernel.  This boot took 36 seconds
 264 (<a href="2005-08-01T21:57-bootchart.png">2005-08-01T21:57-bootchart.tgz</a>).
 265
 266 <p>Next try was to comment out all the entries in /etc/modules, as I
 267 suspect the IDE bus probing is spending a considerable amount of time
 268 at the start of the boot.  Commented out ide-cd, ide-detect, ide-disk
 269 and psmouse.  If these modules are needed on the machine in question,
 270 I expect hotplug and discover to take care of the loading.  I must
 271 have been right, as the boot took 29 seconds
 272 (<a href="2005-08-01T22:01-bootchart.png">2005-08-01T22:01-bootchart.tgz</a>).
 273 Neither of the modules were loaded after boot, and the machine was
 274 still working and the mouse still responsive.
 275
 276 <p>I switched back to gdm, and rebooted with the 2.4 SMP kernel to see
 277 how this change affected SMP.  This boot took 60 seconds
 278 (<a href="2005-08-01T22:06-bootchart.png">2005-08-01T22:06-bootchart.tgz</a>).
 279
 280 </body>
 281 </html>