[SOLVED] Since going multilib, boot time really slow

vdemuth · 05-06-2013, 10:36 AM

Hi,

Just upgraded to multilib as need to be running a specific 32bit program, but since doing so the boot time on my laptop has gone really slow.

Normal boot time to the KDM login screen had previously been around 100 seconds or so. But it's now taking almost 3 x that. Seems to stall around where the fonts are updated, but looking at the system logs, there doesn't seem to be much between 38secs in and 194 seconds.

Code:

[   12.109670] Console: switching to colour frame buffer device 200x56
[   12.123327] radeon 0000:01:05.0: fb0: radeondrmfb frame buffer device
[   12.123329] radeon 0000:01:05.0: registered panic notifier
[   12.123439] [drm] Initialized radeon 2.29.0 20080528 for 0000:01:05.0 on 
minor 0
[   12.123561] snd_hda_intel 0000:01:05.1: setting latency timer to 64
[   12.148160] input: HDA ATI HDMI HDMI/DP,pcm=3 as 
/devices/pci0000:00/0000:00:01.0/0000:01:05.1/sound/card1/input12
[   12.517864] Adding 979960k swap on /dev/sdb2.  Priority:-1 extents:1 
across:979960k 
[   12.626444] fuse init (API version 7.20)
[   13.311547] EXT4-fs (sdb1): re-mounted. Opts: (null)
[   14.072572] ppdev: user-space parallel port driver
[   14.086005] lp: driver loaded but no devices found
[   14.117122] powernow-k8: this CPU is not supported anymore, using 
acpi-cpufreq instead.
[   17.411722] EXT4-fs (sdb3): mounted filesystem with ordered data mode. Opts: 
(null)
[   38.358159] NET: Registered protocol family 10
[  194.829240] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  200.878442] tg3 0000:03:00.0: irq 43 for MSI/MSI-X
[  200.996969] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  201.324915] vboxdrv: Found 2 processor cores.
[  201.325042] vboxdrv: fAsync=0 offMin=0x4c5 offMax=0xcf9
[  201.325110] vboxdrv: TSC mode is 'synchronous', kernel timer mode is 
'normal'.
[  201.325112] vboxdrv: Successfully loaded version 4.2.12 (interface 
0x001a0004).
[  203.198622] vboxpci: IOMMU not found (not registered)
[  208.093727] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  209.842187] pcieport 0000:00:07.0: System wakeup enabled by ACPI
[  209.869719] tg3 0000:03:00.0: irq 43 for MSI/MSI-X
[  209.977152] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  212.128031] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  219.837887] wlan0: authenticate with e0:46:9a:62:fb:25
[  219.847560] wlan0: send auth to e0:46:9a:62:fb:25 (try 1/3)
[  219.851563] wlan0: authenticated
[  219.851798] wlan0: associate with e0:46:9a:62:fb:25 (try 1/3)
[  219.855938] wlan0: RX AssocResp from e0:46:9a:62:fb:25 (capab=0x411 status=0 
aid=4)
[  219.856087] wlan0: associated
[  219.856138] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  267.605419] ata1.00: configured for UDMA/133
[  267.605434] ata1: EH complete
[  267.723998] ata2.00: configured for UDMA/133
[  267.724014] ata2: EH complete
[  268.448598] EXT4-fs (sdb1): re-mounted. Opts: commit=0
[  269.741592] EXT4-fs (sdb3): re-mounted. Opts: commit=0

Any one experienced this and maybe have a pointer in where to start looking for the bottleneck?

TIA

business_kid · 05-06-2013, 11:00 AM

Multilib doesn't affect the boot, unless you made other adjustments. It just adds libs.

Delays are most likely in network log ons. From the snippet of log, this seems to be a big gap

Code:

[  219.856138] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[  267.605419] ata1.00: configured for UDMA/133

vdemuth · 05-06-2013, 11:50 AM

Except this is a similar snippet from the same part of the log from the day previous just before installing the multi lib stuff. As can be seen, the time to the network connection is much less, (132 secs as compared to 219). The only reasonable conclusion is something in them is causing the problem.

Any more ideas?

Code:

[   12.109746] Console: switching to colour frame buffer device 200x56
[   12.123440] radeon 0000:01:05.0: fb0: radeondrmfb frame buffer device
[   12.123442] radeon 0000:01:05.0: registered panic notifier
[   12.123554] [drm] Initialized radeon 2.29.0 20080528 for 0000:01:05.0 on 
minor 0
[   12.407275] Adding 979960k swap on /dev/sdb2.  Priority:-1 extents:1 
across:979960k 
[   12.509759] fuse init (API version 7.20)
[   59.862730] EXT4-fs (sdb1): re-mounted. Opts: (null)
[   59.982607] ppdev: user-space parallel port driver
[   59.995929] lp: driver loaded but no devices found
[   63.396814] EXT4-fs (sdb3): mounted filesystem with ordered data mode. Opts: 
(null)
[   80.684052] NET: Registered protocol family 10
[  114.180322] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  117.766600] vboxdrv: TSC mode is 'synchronous', kernel timer mode is 
'normal'.
[  118.274938] vboxpci: IOMMU not found (not registered)
[  120.104035] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  126.632533] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  127.946597] pcieport 0000:00:07.0: System wakeup enabled by ACPI
[  128.081587] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  128.334153] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[  132.374578] wlan0: authenticate with e0:46:9a:62:fb:25
[  132.393210] wlan0: send auth to e0:46:9a:62:fb:25 (try 1/3)
[  132.395210] wlan0: authenticated
[  132.395832] wlan0: associate with e0:46:9a:62:fb:25 (try 1/3)
[  132.399768] wlan0: RX AssocResp from e0:46:9a:62:fb:25 (capab=0x411 status=0 
aid=5)
[  132.399838] wlan0: associated
[  132.399850] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready

bigrigdriver · 05-06-2013, 12:15 PM

You may have noticed that if there is a problem starting an application, there is a time delay between trying to start the app, and getting an error message.

Take a look at this:

Quote:

[ 38.358159] NET: Registered protocol family 10
[ 194.829240] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready

Start trying to set up the network to getting the error message "link is not ready".

It seems that you need to take a close look at the configuration files to optimize the setting up of the IPv6 network.

vdemuth · 05-06-2013, 12:56 PM

Changed nothing in the network settings since forever basically. The laptop is about 3 years old and has been running on the same wireless router since then, through various different releases of Slackware since. I have had no reason to change anything networking wise for that long as it just works.

But, as a question, where do I find the logs for what happens between 38secs and 194 secs. If it helps, that seems to be when runlevel 4 is started, but before X.

I have scanned through every log I can find and they all stop around 38secs and restart around 194 secs, so a big chunk of something going on with no logging info.

Thanks for the suggestions so far.

business_kid · 05-07-2013, 03:53 AM

Quote:

But, as a question, where do I find the logs for what happens between 38secs and 194 secs. If it helps, that seems to be when runlevel 4 is started, but before X.

Usually, the thing that started at 38 seconds (or something else started just before it) continues for a long time. Nothing happened in that period. That's your problem.

vdemuth · 05-07-2013, 10:54 AM

Quote:

Originally Posted by business_kid

Usually, the thing that started at 38 seconds (or something else started just before it) continues for a long time. Nothing happened in that period. That's your problem.

Everyone keeps telling me this, but it is simply not yhe case that the network setup is the bottleneck.

While watching the computer boot, the lag seem to be around the mime database update and the part where the gtk-immodules are updated. The PC sits here for ages with the hard drive light flashing indicating some serious HD activity. However, I don't know of a way to log the screen messages to put here.

I have tested the HD with a bootable CD running partition magic as it has some good hard drive tools on it, and it passed OK so it's not a hard drive issue.

So any way to find out what all the HD activity is during the long periods of the thing doing nothing else?

Cheers

business_kid · 05-07-2013, 11:55 AM

You can do this stuff yourself, you know, and test it with time. Go to /etc/rc.d/rc.M around line 200. The logic is simple; if the file is executable, run it. Have you rc.wicd or rc.networkmanager set executable???

You can check the update stuff by just timing the command

Code:

time  /usr/bin/update-gtk-immodules --verbose

vdemuth · 05-07-2013, 01:12 PM

Hi there,

Thanks for the tip.

This is what I have when timing the startup scripts from rc.M

Code:

# These GTK+/pango files need to be kept up to date for
# proper input method, pixbuf loaders, and font support.
if [ -x /usr/bin/update-gtk-immodules ]; then
time /usr/bin/update-gtk-immodules --verbose
fi
if [ -x /usr/bin/update-gdk-pixbuf-loaders ]; then
time /usr/bin/update-gdk-pixbuf-loaders --verbose
fi
if [ -x /usr/bin/update-pango-querymodules ]; then
time /usr/bin/update-pango-querymodules --verbose
fi

That takes 1m28.080s,

Seems to me to be something not quite right there.

I also have another part of the script that take around 10 secs or so,

Code:

# Update the X font indexes:
if [ -x /usr/bin/fc-cache ]; then
  echo "Updating X font indexes:  /usr/bin/fc-cache -f &"
time /usr/bin/fc-cache -f & --verbose
fi

All the network related stuff, including wicd starts in less than .5 sec.

Any suggestions on speeding this up. I know that plenty of people say not to bother about boot times and ordinarily I would agree with them if I were talking about a server or desktop, but as this is a laptop which gets switched off when not being used it's a bit of a PITA to say the least.

Thanks

business_kid · 05-08-2013, 03:29 AM

That should give 3 times. It might also have to wait for the network to come up. Of course you now have 32 bit modules as well. Just running those from the command line here in a multilib box

Code:

bash-4.2# time /usr/bin/update-gtk-immodules --verbose
Updating gtk.immodules for x86_64-slackware-linux:
  /usr/bin/gtk-query-immodules-2.0-64 \
  > /etc/gtk-2.0/x86_64-slackware-linux/gtk.immodules
Updating gtk.immodules for x86_64-slackware-linux:
  /usr/bin/gtk-query-immodules-3.0-64 \
  > /etc/gtk-3.0/x86_64-slackware-linux/gtk.immodules

real	0m0.075s
user	0m0.051s
sys	0m0.018s
bash-4.2# time /usr/bin/update-gdk-pixbuf-loaders --verbose
Updating gdk-pixbuf.loaders for x86_64-slackware-linux:
  /usr/bin/gdk-pixbuf-query-loaders-64 --update-cache
Updating gdk-pixbuf.loaders for i486-slackware-linux:
  /usr/bin/gdk-pixbuf-query-loaders-32 --update-cache

real	0m0.063s
user	0m0.033s
sys	0m0.013s
bash-4.2# time /usr/bin/update-pango-querymodules --verbose
Updating pango.modules for x86_64-slackware-linux:
  /usr/bin/pango-querymodules-64 \
  > /etc/pango/x86_64-slackware-linux/pango.modules
Updating pango.modules for i486-slackware-linux:
  /usr/bin/pango-querymodules-32 \
  > /etc/pango/i486-slackware-linux/pango.modules

real	0m0.046s
user	0m0.036s
sys	0m0.007s
bash-4.2# which gtk-query-immodules-2.0-64
/usr/bin/gtk-query-immodules-2.0-64
bash-4.2# which gdk-pixbuf-query-loaders-32
/usr/bin/gdk-pixbuf-query-loaders-32

Thatś not 1m28s. Go figure.They all are scripts.

vdemuth · 05-08-2013, 03:53 AM

Hi again,

the three times are:

Code:

if [ -x /usr/bin/update-gtk-immodules ]; then
time /usr/bin/update-gtk-immodules --verbose
fi

real	0m40.216s
user	0m12.374s
sys	0m3.664s
if [ -x /usr/bin/update-gdk-pixbuf-loaders ]; then
time /usr/bin/update-gdk-pixbuf-loaders --verbose
fi

real	0m18.682s
user	0m0.067s
sys	0m0.040s
if [ -x /usr/bin/update-pango-querymodules ]; then
time /usr/bin/update-pango-querymodules --verbose
fi

real	0m6.082s
user	0m0.058s
sys	0m0.046s

These are timings from the last boot up run from rc.M, so a little different from the first set I gave, but you get the idea. I see that your times are really short, so still not quite understanding what's going on.
I'll go and mod the rc.M script to write the results to a file and post it up here to see if you are able to spot anything I might be missing.

Thanks for your patience and assistance so far.

business_kid · 05-08-2013, 04:15 AM

Ok. So go to it. Each of the scripts are like rc.M and you can time whatś going on. There is redundancy, and --verbose is telling you nothing. Youĺl find something, and tell us what it is.

pan64 · 05-08-2013, 05:49 AM

actually I would try to switch off ipv6

vdemuth · 05-10-2013, 12:15 PM

Right, as I suspected, it seems to be to do with the gtk-update part of the script as can be seen from the info below:

Code:

Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/matefaenzadark"
	User time (seconds): 0.97
	System time (seconds): 0.41
	Percent of CPU this job got: 2%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:58.68
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 60448
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 5209
	Voluntary context switches: 1644
	Involuntary context switches: 211
	Swaps: 0
	File system inputs: 18704
	File system outputs: 16824
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
User time (seconds): 0.59
	System time (seconds): 0.25
	Percent of CPU this job got: 1%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:59.50
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 30704
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 2
	Minor (reclaiming a frame) page faults: 2974
	Voluntary context switches: 1022
	Involuntary context switches: 109
	Swaps: 0
	File system inputs: 10968
	File system outputs: 4768
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/matefaenzagray"
	User time (seconds): 0.79
	System time (seconds): 0.32
	Percent of CPU this job got: 1%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:59.09
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 54384
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 4469
	Voluntary context switches: 1136
	Involuntary context switches: 188
	Swaps: 0
	File system inputs: 12536
	File system outputs: 15608
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/nuvola"
	User time (seconds): 3.38
	System time (seconds): 0.87
	Percent of CPU this job got: 3%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 1:56.49
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 257056
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 19917
	Voluntary context switches: 3882
	Involuntary context switches: 787
	Swaps: 0
	File system inputs: 46344
	File system outputs: 98080
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
	Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/mate"
	User time (seconds): 3.05
	System time (seconds): 0.83
	Percent of CPU this job got: 3%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 1:57.51
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 349296
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 24667
	Voluntary context switches: 2857
	Involuntary context switches: 680
	Swaps: 0
	File system inputs: 41056
	File system outputs: 148576
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
	Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/gnome"
	User time (seconds): 3.15
	System time (seconds): 0.79
	Percent of CPU this job got: 3%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 1:58.30
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 395056
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 27394
	Voluntary context switches: 2656
	Involuntary context switches: 807
	Swaps: 0
	File system inputs: 48864
	File system outputs: 171736
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/hicolor"
	User time (seconds): 3.86
	System time (seconds): 0.97
	Percent of CPU this job got: 3%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 2:32.70
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 787040
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 1
	Minor (reclaiming a frame) page faults: 30794
	Voluntary context switches: 3149
	Involuntary context switches: 1138
	Swaps: 0
	File system inputs: 61072
	File system outputs: 335936
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/default.kde4"
	User time (seconds): 8.67
	System time (seconds): 1.76
	Percent of CPU this job got: 5%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 3:28.73
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 846960
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 60456
	Voluntary context switches: 7746
	Involuntary context switches: 4130
	Swaps: 0
	File system inputs: 50792
	File system outputs: 366784
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0
Command exited with non-zero status 1
	Command being timed: "/usr/bin/gtk-update-icon-cache -t -f /usr/share/icons/oxygen"
	User time (seconds): 8.72
	System time (seconds): 1.79
	Percent of CPU this job got: 5%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 3:28.49
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 763440
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 55019
	Voluntary context switches: 7749
	Involuntary context switches: 4455
	Swaps: 0
	File system inputs: 64880
	File system outputs: 366784
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0

So in total 47.74 seconds just updating icons?

Does that seem right?

Any ideas anyone as to why this might be and how to correct it?

Thanks

business_kid · 05-10-2013, 02:06 PM

No, it doesn't seem right. I'd google this one

Quote:

Minor (reclaiming a frame) page faults: 5209

and I'd check that cache, and what's going on. You're nearly there. Maybe it's not writing or reading due to some permissions thing. A cache should be collected and stay. I have multilib, and you have my times