What is GRUB doing while it takes 9 minutes to start booting the kernel?

Question

Lately (at least the last 2 time I turned the PC on) I noticed grub takes forever to boot. I timed almost 9 minutes between the bios messages go away and the kernel log appears on screen.

The question is how can I know what grub is doing or waiting? How can I check grub is ok?

A few days ago I removed the splash screen so I see the text log on every boot. Most of the times it is fast and normal. During those 9 minutes the monitor receives signal, but it is just a black screen. NumLock does not respond, the whole thing appears to be frozen, but it is not.

I have have / on a software raid1 since 2009 at least.

The raid is reported healthy. During those minutes there's some minor hard disk activity in the first minute. Hard drive SMART data is healthy. Shutdown the day before was normal.

I have had all Ubuntu versions installed in this computer since 8.04. I have 12.10 installed since October. There's nothing new in this computer, no new hard drives, no changes in the BIOS settings.

There's no grub log AFAIK and the kernel log is not interesting because it says the kernel booted in 28 seconds [PhenomX4 kernel: [ 28.825313] vboxpci: IOMMU not found (not registered)] so the 9 minutes are before the kernel started.

*Update: march 27th *

I found the problem, but I still don't know the cause. The problem was /boot/grub/grub.cfg was 11.6 MB and it had entries like this one repeated many many times with slight variations. Grub was choking on such a big file to create its menu.

menuentry 'Ubuntu 12.10 (12.10) (en /dev/sda1) (en /dev/sda1) (en /dev/sdb1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1) (en /dev/sda1)' --class gnu-linux --class gnu --class os $menuentry_id_option 'osprober-gnulinux-/vmlinuz--73e06880-5f46-4493-aaef-23fa4ad138f6' {
    insmod part_msdos
    insmod ext2
    set root='hd0,msdos1'
    if [ x$feature_platform_search_hint = xy ]; then
      search --no-floppy --fs-uuid --set=root --hint-bios=hd0,msdos1 --hint-efi=hd0,msdos1 --hint-baremetal=ahci0,msdos1 --hint='hd0,msdos1'  73e06880-5f46-4493-aaef-23fa4ad138f6
    else
      search --no-floppy --fs-uuid --set=root 73e06880-5f46-4493-aaef-23fa4ad138f6
    fi
    linux /vmlinuz root=/dev/sda1
    initrd /initrd.img
}

Still don't know why that file grew so much?

Update march 28th

A big chunk of the menu entries is generated by /etc/grub.d/30_os-prober.

Line 223: ### BEGIN /etc/grub.d/30_os-prober ###
...
Line 175174: ### END /etc/grub.d/30_os-prober ###

grub.cfg has 175191 lines, so that script represents 99% of the 11.6 MB in the file.

Answer 1

There's a nice tool called BootChart included in the repositories. It also has a GRUB debug component provided. these will allow you to profile your boot and hopefully find out what's eating the large chunk of time.

Answer 2

If you get all those entries probably there is something making a loop on Grub. It happened a similar thing to me when installed Raring on a separate partition (bad escaping created entries like menuentry "Ubuntu"...). As you said you changed nothing maybe this has origin in some update in Grub?

That file is automatically generated (when you install a new kernel, for example) by the scripts present in /etc/grub.d. If you examine grub.cfg you will see that there are separators between entries, specifying which script generated it. Example:

### BEGIN /etc/grub.d/30_uefi-firmware ###
### END /etc/grub.d/30_uefi-firmware ###

### BEGIN /etc/grub.d/40_custom ###
# This file provides an easy way to add custom menu entries.  Simply type the
# menu entries you want to add after this comment.  Be careful not to change
# the 'exec tail' line above.
menuentry "Ubuntu Raring (on /dev/sda2)" --class gnu-linux --class gnu --class os {
    (...)
}

menuentry 'Steam' --class ubuntu --class gnu-linux {
        (...)
}
### END /etc/grub.d/40_custom ###

### BEGIN /etc/grub.d/41_custom ###
if [ -f  $prefix/custom.cfg ]; then
  source $prefix/custom.cfg;
fi
### END /etc/grub.d/41_custom ###

So try to identify which script is creating those entries (and update your answer with the script name). When you get there, you can use sudo grub-mkconfig or execute that script using, for example:

sh -v /etc/grub.d/file

to try to identify what is going on.

This is not a solution at all, but I hope it could help in something.