LinuxQuestions.org

LinuxQuestions.org (/questions/)
-   Slackware (http://www.linuxquestions.org/questions/slackware-14/)
-   -   Since going multilib, boot time really slow (http://www.linuxquestions.org/questions/slackware-14/since-going-multilib-boot-time-really-slow-4175460903/)

vdemuth 05-06-2013 11:36 AM

Since going multilib, boot time really slow
 
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 12:00 PM

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 12:50 PM

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 01: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 01: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 04: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 11:54 AM

Quote:

Originally Posted by business_kid (Post 4946444)
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 12:55 PM

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 02: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 04: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 04: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 05: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 06:49 AM

actually I would try to switch off ipv6

vdemuth 05-10-2013 01: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 03: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


All times are GMT -5. The time now is 10:51 AM.