[SOLVED]30 second pause during boot

[disastrophe]

Hi,
I've been using pclos for a couple of months now and I currently have both the KDE and E17 editions installed on my main box. Anyway, over the last couple of days I have been running into a significant pause during boot where there is no HDD activity and no overt errors being reported in the logs.
The pause averages 30 secs and it occurs with both editions. It just started doing it yesterday.
Normally the system is completely booted and at a usable desktop within 25 -30 secs so this pause has more than doubled my boot time and is somewhat troublesome.
I was perusing the logs and while I did not see any errors, I did see the lag in message time stamps.
Here are some excerpts from both syslog and messages.

Syslog:

Code: [Select]

Dec  9 04:10:40 localhost ntpd[2888]: kernel time sync status 0040
Dec  9 04:10:40 localhost ntpd[2888]: frequency initialized -24.476 PPM from /var/lib/ntp/drift
Dec  9 04:10:40 localhost klogd: netfilter PSD loaded - (c) astaro AG
Dec  9 04:10:40 localhost klogd: IFWLOG: register target
Dec  9 04:10:40 localhost logger: Shorewall started
Dec  9 04:10:40 localhost klogd: usbcore: registered new interface driver snd-usb-audio
Dec  9 04:10:45 localhost klogd: eth0: no IPv6 routers present
Dec  9 04:10:52 localhost klogd: ata1.00: configured for UDMA/100
Dec  9 04:10:52 localhost klogd: ata1: EH complete
Dec  9 04:11:04 localhost net_applet[3299]: ### Program is starting ###         <<<< note pause
Dec  9 04:11:31 localhost drakconf.real[3351]: ### Program is starting ###     <<<<
Dec  9 04:11:38 localhost drakconf.real[3361]: ### Program is starting ###
Dec  9 04:11:46 localhost logdrake[3385]: ### Program is starting ###
Dec  9 04:13:55 localhost ntpd[2888]: synchronized to LOCAL(0), stratum 10
Dec  9 04:13:55 localhost ntpd[2888]: kernel time sync status change 0001
Messages:

Code: [Select]

Dec  9 04:10:40 localhost ntpd[2888]: kernel time sync status 0040
Dec  9 04:10:40 localhost ntpd[2888]: frequency initialized -24.476 PPM from /var/lib/ntp/drift
Dec  9 04:10:40 localhost klogd: netfilter PSD loaded - (c) astaro AG
Dec  9 04:10:40 localhost klogd: IFWLOG: register target
Dec  9 04:10:40 localhost logger: Shorewall started
Dec  9 04:10:40 localhost klogd: usbcore: registered new interface driver snd-usb-audio
Dec  9 04:10:52 localhost klogd: ata1.00: configured for UDMA/100
Dec  9 04:10:52 localhost klogd: ata1: EH complete
Dec  9 04:11:04 localhost net_applet[3299]: ### Program is starting ###          <<<< And here
Dec  9 04:11:31 localhost drakconf.real[3351]: ### Program is starting ###      <<<<
Dec  9 04:11:38 localhost drakconf.real[3361]: ### Program is starting ###
Dec  9 04:11:46 localhost logdrake[3385]: ### Program is starting ###

It looks like the net_applet or something related. This just started yesterday and neither my Arch or Debian installs have any lag at all. (I boot 4 distros on this box) I am on a hard wired +50Mb/s always on, cable internet connection. And to reiterate, only pclos has this lag.
Anybody else experiencing this? Any ideas on fixing it?
Thanks in advance.  

  

[cyrwyn]

I've seen this before, but it may not be caused by the same problem. It's a delay while starting a service, probably net related, so it will not show up as an error in the logs. Press the Esc key when the bootup splash screen appears and watch the text output. Did you know this? When the delay is over and the next line appears with an OK, that is where the problem is.

[uncleV]

At boot time when your splash theme shows hit "Esc" for to be able to see the boot messages "behind" it. There you should see where the delay is.

[disastrophe]

At boot time when your splash theme shows hit "Esc" for to be able to see the boot messages "behind" it. There you should see where the delay is.

Sorry, it's early and I needed another couple of cups of coffee. Anyway, it is hanging trying to mount the swap partition. I installed another Arch and it formatted sda8 (my swap partition) and since PCLOS uses UUID by default it couldn't find it. So I changed /etc/fstab accordingly but it's still pausing at:  

Code: [Select]

Waiting for /dev/sda8 to appear

Massive edit
The swap is enabled and working:

Code: [Select]

[anton@localhost ~]$ cat /proc/meminfo
SwapTotal:       1951736 kB
SwapFree:        1951736 kB


Code: [Select]

[anton@localhost ~]$ swapon -s
Filename                                Type            Size    Used    Priority
/dev/sda8                               partition       1951736 0       -1

So, what else could be causing it to pause there? The time it appeared does coincide with the new Arch install. All the UUIDs in fstab check out so maybe it's something else entirely that isn't appearing in the bootup messages?
Here's my fstab

Code: [Select]

[anton@localhost ~]$ cat /etc/fstab
# Entry for /dev/sda9 :
UUID=8dbc041c-c7fb-41dd-abff-ea52544c5359 / ext4 noatime,defaults 1 1
# Entry for /dev/sda10 :
UUID=570a07f4-4709-4b6d-87bb-2e682ef64227 /home ext4 noatime,defaults 1 2
none /proc proc defaults 0 0
# Entry for /dev/sda8 :
#UUID=151d07da-86a6-44f0-bf29-9f3f41ae32c5 swap swap defaults 0 0
/dev/sda8 swap swap defaults 0 0
none /dev/pts devpts defaults 0 0
# UUID sda13
UUID=2217a00a-d110-42b7-8a8d-a7c7154ad6fb /storage2       ext3    noatime,defaults  0  0
# UUID sda14
UUID=406977e8-3c37-45ec-a6bc-01c1454469aa /storage3       ext4    noatime,defaults  0  0
The corresponding blkid output:

Code: [Select]

/dev/sda8: UUID="151d07da-86a6-44f0-bf29-9f3f41ae32c5" TYPE="swap"
/dev/sda9: UUID="8dbc041c-c7fb-41dd-abff-ea52544c5359" TYPE="ext4"
/dev/sda10: UUID="570a07f4-4709-4b6d-87bb-2e682ef64227" TYPE="ext4"
/dev/sda13: LABEL="Data2" UUID="2217a00a-d110-42b7-8a8d-a7c7154ad6fb" TYPE="ext3" SEC_TYPE="ext2"
/dev/sda14: LABEL="Data3" UUID="406977e8-3c37-45ec-a6bc-01c1454469aa" TYPE="ext4"
And my fdisk -l ouput

Code: [Select]

/dev/sda1   *        2048    23437311    11717632   83  Linux
/dev/sda2        23439358   703281151   339920897    5  Extended
/dev/sda5        23439360    42969087     9764864   83  Linux
/dev/sda6        42971136    66406399    11717632   83  Linux
/dev/sda7        66408448    85938175     9764864   83  Linux
/dev/sda8        85940224    89843711     1951744   82  Linux swap / Solaris
/dev/sda9        89845760   113281023    11717632   83  Linux
/dev/sda10      113283072   132812799     9764864   83  Linux
/dev/sda11      132814848   156250111    11717632   83  Linux
/dev/sda12      156252160   175781887     9764864   83  Linux
/dev/sda13      351565824   527345663    87889920   83  Linux
/dev/sda14      527347712   703281151    87966720   83  Linux
/dev/sda15      175783936   216743935    20480000   83  Linux
/dev/sda16      216745984   247465983    15360000   83  Linux
/dev/sda17      247481388   277603199    15060906   83  Linux
/dev/sda18      277603263   298037879    10217308+  83  Linux
/dev/sda19      298037943   304030124     2996091   82  Linux swap / Solaris
/dev/sda20      304030188   331372754    13671283+  83  Linux
/dev/sda21      331372818   351550394    10088788+  83  Linux

Everything looks correct and the pause is only occuring with my PCLOS installs. Arch boots in about 10 secs, Sid in about 13 secs and PCLOS (KDE) in about 70 secs. Something ain't right, that's for sure. I would be pulling my hair out if that was possible.
 

[uncleV]

... but it's still pausing at:  

Code: [Select]

Waiting for /dev/sda8 to appear

All I know about this is that I saw several times similar issues reported here at the forum, some of them solved.

Just do Search with the string

Code: [Select]

"waiting for" /dev/ "to appear"and there'll appear may be something useful for you.

[disastrophe]

After browsing through /var/log I found something interesting in kdm.log.

Code: [Select]

(==) Log file: "/var/log/Xorg.0.log", Time: Thu Dec  9 12:40:29 2010
(==) Using config file: "/etc/X11/xorg.conf"
FATAL: Module fbcon not found.
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'
FreeType: couldn't find encoding 'iso8859-14' for '/etc/X11/fontpath.d/../../../usr/share/fonts/TTF/droid/DroidSansMono.ttf'

Xorg.0.log is showing the same and Thu Dec  9 12:40:29 2010 was my current session start with PCLOS. This is kind of odd cause I've been using Droid for a while now. Maybe I'm on to something? It's the "Module fbcon not found" that concerns me.

Edit: There appears to be a known issue with Mandriva when installing other OSs concurrently and when they prep the swap partition.(It is very odd that the system was using it though, that part of it doesn't fit) The suggested solution is to remake the initial rd so I'll try that the next time I boot into PCLOS.

[kjpetrie]

You need to remake your initrd:
mkinitrd /boot/initrd-`uname -r`.img `uname -r` as root should do the trick. (Those are backticks, not apostrophes.)

Also, don't forget to edit /boot/grub/menu.lst if you have the resume kernel option there.

[disastrophe]

Thanks. The resume thing in Grub was one of the first places I looked actually. Anyway, I'll remake the initrd the next time I boot into pclos. 

[disastrophe]

Well I got to wonderin' and so I went ahead and rebooted. Ran a mkinitrd -f and it worked like a charm. (you need the -f parameter to overwrite the previous initrd) You also want to clean out the garbage it leaves at the tail of /boot/grub/menu.lst.  Anyway, I'm back to about a 20 second boot for pclos, maybe even a little less.
Thanks for the replies everybody and have a great fri/weekend!  
Marking this as solved.

[dpeirce]

Thanks kjpetrie. I was poking around and found this thread by accident. I've had that delay problem for a month or more but just lived with it. I figured maybe y'all just wanted me to look at your logo for a while - good advertising .

But I did # mkinitrd -f /boot/initrd-`uname -r`.img `uname -r` and rebooted; no hangups, the logo went away quickly, and it booted quickly.

I'm not knowledgeable enough to figure out from disastrophe's quoted code why it was getting hung up and making the delay. Could someone explain it for me (on about a third grade level, please)?

In faith, Dave
Viva Texas

It's a little-known fact that the Y1K problem caused the Dark Ages.

[boundzy]

Just stumbled on this thread. I'd noticed slower boot times recently, but had not thought too much about it. Remaking the initrd worked -- boot time is much quicker.

Not sure why this worked, but it did.

Thanks!

[kjpetrie]

initrd is the initial RAM disc - a file which contains a copy of vital parts of the / file system such as kernel modules and /etc/fstab, which will be copied into a virtual fs in RAM for the kernel to use when it first boots. This is where the kernel gets the information it needs to mount the real file system when the time comes. So if there is a change to fstab the kernel will need to know about before it can mount the real / (or swap) partition that change needs to be copied to the fstab in the initrd, and the easiest way to do that is to remake the whole file.

That's my simple layman's understanding.

[boundzy]

Thanks for the explanation, kjpetrie! That makes sense, generally. 

From your earlier post, it appears that this issue (longer boot times) was specific to systems with multiple OSs? I have both PCLOS (KDE) and W7 on my laptop, though I can count on one hand the number of times I've booted into W7 over the past 5 months.

I assume that an update I performed through Synaptic changed something in the initial rd causing the longer boot times on systems with multiple OSs and necessitated running mkinitrd to "reset" it? Am I even in the ballpark?

Also, I did not notice any changes to my /boot/grub/menu.lst file after running mkinitrd.

Again, thanks for the info!

[kjpetrie]

What usually starts the problem is a change to the UUID of a partition. This can be caused by running a partitioning program such as the installer for an operating system. Ideally, a partitioner should leave pre-existing partitions alone unless told to modify them, but sometimes things are not ideal.

Most OS installers seem to start from the basis they are the only OS that matters.

[Old-Polack]

boundzy:

To add to what kjpetrie said, one of the main reasons for the problem is user error, when installing a second Linux OS. With the first Linux OS, it's necessary to create a swap partition, which then gets a UUID number. With additional Linux OS, there is no need to specify a swap partition, in any manner, during the partitioning phase; if one exists, the new OS will use it as is. If the user selects the existing swap partition specifically, when designating partitions to be used for the new installation, during the partitioning phase, the installer will then reformat the swap partition, thereby giving it a new UUID number. All other installations using the old swap UUID will now need to have their initrd image updated.

When I add another OS, I only designate the new / partition, and set it to not be formatted, as I do this prior to the installation. The only time I mention the swap partition is during the grub install phase, when I set the resume partition for the grub stanzas. I have yet to have an existing swap partition reformatted by an installer.