Thursday, February 02, 2006

System start up time

To follow on from why I use windows, I just did some (unscientific) start-up timings on my SunBlade 1500 running Solaris 10 Update 1.

Time in seconds from pressing the on button:

  1. Solaris license terms: 41s
  2. Console Login prompt: 104s
  3. Desktop Login prompt: 133s
  4. JDS start: 165s
  5. JDS ready: 190s
  6. Terminal ready to type: 199s

There's a 30 second hole in the middle where I'm typing in my username and password (and writing down the numbers) where 10 seconds would be more reasonable, so the full length of time to actual login is almost exactly 3 minutes. (And then another 20 seconds to open Mozilla.)

(I've broken the graphical startup into 2 phases, dtlogin start and JDS start, with the human typing in the middle. The whole graphical login process takes about a minute of the 3, with the general boot taking the other 2 minutes. OK, so it's possible to make the gui startup much quicker, but there's still the whole hardware phase and kernel boot to get past.)

What's the machine been doing all this time? A quick look at iostat immediately afterwards:

extended device statistics
r/s w/s kr/s kw/s wait actv wsvc_t asvc_t %w %b device
74.5 3.5 824.7 37.0 0.3 0.8 4.3 9.7 13 46 c0t0d0

Or in raw terms from kstat:

reads 10986
writes 482
nread 124590592
nwritten 5022208

So during boot I read 125M of data off the disk, in 11,000 reads. And this actually only covers about 2/3 of the boot - it isn't until about a minute into the boot that the kstats are created. If you allow for the login delay while I'm typing username and password and the few seconds it takes to actually run the above commands, and you can see that the disk is actually well over 50% busy during the boot. Based on the disk activity, boot times can't improve by better than a factor of 2 unless the disk access pattern changes (larger reads than the average 11k seen here would help).

The cpu statistics can also be obtained:

cpu_nsec_idle 102634677402
cpu_nsec_kernel 44861276123
cpu_nsec_user 25778566225

Remember that these numbers don't cover the first 1/3 of the boot. (And they don't add up, either, as I make that 170s which is more than the 140s between crtime and snaptime.) But looking at it, the processor is less than 50% busy.

I'm not sure how to look at these numbers and convert them into the sort of boot-time improvements that might be made, but taking the 50% resource utilization at face value indicates that the portion of the boot covered by the kstat collection could be sped up by a factor 2, which takes the overall cold start from 3 minutes to 2. That wouldn't be bad, would it?

No comments: