Slow program launch. Is this normal and how to fix it?

guanx · 03-10-2009, 01:27 PM

Quote:

Originally Posted by H_TeXMeX_H

That dd test is not as clear a benchmark as you might think, it's not a linear relationship:

The hdparm -tT is the most consistent test.

Use "fdatasync". See "man dd". The hdparm tests reading, not writing, I think.

H_TeXMeX_H · 03-10-2009, 02:16 PM

Interesting, I didn't know what that option did, but you're right now the results are much more comparable and perhaps useful:

Code:

bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=1000
1000+0 records in
1000+0 records out
262144000 bytes (262 MB) copied, 4.60565 s, 56.9 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=1000 conv=fdatasync
1000+0 records in
1000+0 records out
262144000 bytes (262 MB) copied, 5.29181 s, 49.5 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=500 conv=fdatasync
500+0 records in
500+0 records out
131072000 bytes (131 MB) copied, 2.06997 s, 63.3 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=100 conv=fdatasync
100+0 records in
100+0 records out
26214400 bytes (26 MB) copied, 0.45019 s, 58.2 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=5000 conv=fdatasync
5000+0 records in
5000+0 records out
1310720000 bytes (1.3 GB) copied, 29.6797 s, 44.2 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=1000 conv=fsync
1000+0 records in
1000+0 records out
262144000 bytes (262 MB) copied, 5.10063 s, 51.4 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=500 conv=fsync
500+0 records in
500+0 records out
131072000 bytes (131 MB) copied, 2.05835 s, 63.7 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=2000 conv=fsync
2000+0 records in
2000+0 records out
524288000 bytes (524 MB) copied, 10.9581 s, 47.8 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=5000 conv=fsync
5000+0 records in
5000+0 records out
1310720000 bytes (1.3 GB) copied, 30.2539 s, 43.3 MB/s
bash-3.1$ dd if=/dev/zero of=1.bin bs=256k count=50 conv=fsync
50+0 records in
50+0 records out
13107200 bytes (13 MB) copied, 0.223791 s, 58.6 MB/s

mbvo · 03-10-2009, 02:53 PM

this is just a guess, but are you using runlevel 3? or 4? and do you have mysql installed? mysql has failed on me a few times and running in level 3 i can see mysql was crashing and restarting itself repeatedly the whole time the computer was running resulting in the computer taking nearly twice as much time to do anything.

also im running on a 266 mhz p2 with 400 mb pc100 and neomagic 4mb video card, and it takes bout 15 seconds max for ff to start yours should outperform mine majorly.

ErV · 03-10-2009, 09:32 PM

Quote:

Originally Posted by H_TeXMeX_H

Try "anticipatory".

No effect. First launch:
Firefox - 20 seconds
Opera - 10 seconds
KMail - 7 seconds
Nvidia-settings - 4 seconds.
As I said - I experience slowdown only at first launch. At the first launch of any of those program hdd is being heavily accessed. At the second, "fast" launch it looks like all files are loaded from RAM cache (HDD led doesn't even blink when program loads quickly).

Quote:

Originally Posted by mbvo

this is just a guess, but are you using runlevel 3? or 4? and do you have mysql installed?

runlevel 4, mysql not running (installed, disabled).

Quote:

Originally Posted by mbvo

also im running on a 266 mhz p2 with 400 mb pc100 and neomagic 4mb video card, and it takes bout 15 seconds max for ff to start yours should outperform mine majorly.

I know it should outperform, but it clearly doesn't do that and shows nearly similar launch time instead.
--EDIT--
I've tried this article:
http://en.opensuse.org/Speeding_up_Ext3
Switching journal mode on root partition and enabling "noatime" gives small performance boost, but still doesn't significantly decrease start times:
firefox - 18 seconds,
opera - 7 seconds
kmail - 7 seconds.
nvidia-settings - 2.9 seconds

Does anyone here has machine that runs slackware and can run any of those in less-than-second time after cold boot? Or at least less than in three seconds (for firefox, opera, kmail)?

I also found article which explains how to flush filesystem caches without rebooting machine:
http://wiki.services.openoffice.org/...tart-simulator

guanx · 03-11-2009, 02:22 AM

Core Duo U2500 / 2GB / Firefox-3.0.3 / Linux-2.6.28.1

Homepage is "about:blank".

Time result of immediate close after first start (average over several tries):

1. When Firefox is on a 250GB SATA disk:
real about 8.0s (my reaction time of about 0.5s is substracted)
user 4.4s
sys 0.45s

2. When firefox is on a USB flash drive (read=18~19MB/s):
real about 7.5s (my reaction time of about 0.5s is substracted)
user 4.3s
sys 0.45s

So we know:

1. Firefox starts very slowly;
2. Disk seek time is not the main cause.

ErV · 03-11-2009, 04:49 AM

Quote:

Originally Posted by guanx

So we know:

1. Firefox starts very slowly;
2. Disk seek time is not the main cause.

What about other software? Reducing launch time of kmail/etc would be nice.

Anyway, I tried profiling the system with oprofile after flushing caches, and got following results (generated using opreport -l)

firefox launch:

Code:

Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        app name                 symbol name
14193    24.0559  libxul.so                /usr/lib/firefox-3.0.6/libxul.so
14063    23.8356  no-vmlinux               /no-vmlinux
9189     15.5746  libmozjs.so              /usr/lib/firefox-3.0.6/libmozjs.so
2649      4.4898  libc-2.7.so              strcmp
2298      3.8949  libsqlite3.so            /usr/lib/firefox-3.0.6/libsqlite3.so
2016      3.4169  libjemalloc.so           /usr/lib/firefox-3.0.6/libjemalloc.so
1141      1.9339  libfontconfig.so.1.3.0   /usr/lib/libfontconfig.so.1.3.0
965       1.6356  libc-2.7.so              memcpy
885       1.5000  libqt-mt.so.3.3.8        /usr/lib/qt-3.3.8b/lib/libqt-mt.so.3.3.8
741       1.2559  libnspr4.so              /usr/lib/firefox-3.0.6/libnspr4.so
730       1.2373  Xorg                     /usr/bin/Xorg
674       1.1424  libpthread-2.7.so        pthread_mutex_lock

kmail launch:

Code:

Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        app name                 symbol name
18128    32.9229  no-vmlinux               /no-vmlinux
5673     10.3029  libqt-mt.so.3.3.8        /usr/lib/qt-3.3.8b/lib/libqt-mt.so.3.3.8
3552      6.4509  ld-2.7.so                do_lookup_x
3480      6.3201  ld-2.7.so                strcmp
3369      6.1186  libc-2.7.so              strcmp
2979      5.4103  ld-2.7.so                check_match.8290
1791      3.2527  libX11.so.6.2.0          /usr/lib/libX11.so.6.2.0
1352      2.4554  libXfont.so.1.4.1        /usr/lib/libXfont.so.1.4.1
1281      2.3265  libc-2.7.so              _int_malloc
1099      1.9959  libkdecore.so.4.2.0      /usr/lib/libkdecore.so.4.2.0
772       1.4021  Xorg                     /usr/bin/Xorg
763       1.3857  libstdc++.so.6.0.9       /usr/lib/libstdc++.so.6.0.9
744       1.3512  libc-2.7.so              _int_free
671       1.2186  libc-2.7.so              memcpy
658       1.1950  nvidia_drv.so            /usr/lib/xorg/modules/drivers/nvidia_drv.so
655       1.1896  libc-2.7.so              malloc
596       1.0824  libz.so.1.2.3            /usr/lib/libz.so.1.2.3

opera launch:

Code:

Counted CPU_CLK_UNHALTED events (Cycles outside of halt state) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        app name                 symbol name
13841    23.7883  no-vmlinux               /no-vmlinux
13634    23.4326  opera                    /usr/local/lib/opera/9.63/opera
2750      4.7264  libc-2.7.so              strcmp
2682      4.6095  ld-2.7.so                do_lookup_x
2430      4.1764  libX11.so.6.2.0          /usr/lib/libX11.so.6.2.0
1570      2.6983  libXfont.so.1.4.1        /usr/lib/libXfont.so.1.4.1
1329      2.2841  libGL.so.180.29          /usr/lib/libGL.so.180.29
1276      2.1930  ld-2.7.so                strcmp
1269      2.1810  libqt-mt.so.3.3.8        /usr/lib/qt-3.3.8b/lib/libqt-mt.so.3.3.8
1164      2.0005  ld-2.7.so                check_match.8290
1010      1.7359  Xorg                     /usr/bin/Xorg
938       1.6121  libc-2.7.so              _int_malloc
832       1.4299  libc-2.7.so              fgetc
793       1.3629  nvidia_drv.so            /usr/lib/xorg/modules/drivers/nvidia_drv.so
706       1.2134  libfontconfig.so.1.3.0   /usr/lib/libfontconfig.so.1.3.0
656       1.1275  libc-2.7.so              __gconv_transform_utf8_internal
610       1.0484  libz.so.1.2.3            /usr/lib/libz.so.1.2.3
592       1.0175  bash                     /bin/bash

It looks like that (except firefox), most time during launch is spent within kernel, but it is hard to say where (oprofile needs vmlinux file to profile kernel, and vmlinux is too big to be handled by lilo, and oprofile refuses to accept it).

H_TeXMeX_H · 03-11-2009, 04:58 AM

Quote:

Originally Posted by ErV

It looks like that (except firefox), most time during launch is spent within kernel, but it is hard to say where (oprofile needs vmlinux file to profile kernel, and vmlinux is too big to be handled by lilo, and oprofile refuses to accept it).

So lilo is involved ? If so, try grub.

ErV · 03-11-2009, 05:28 AM

Quote:

Originally Posted by H_TeXMeX_H

try grub.

Which one - "grub 2" or "grub legacy"?
Anyway, changing bootloader will have to wait at least until tomorrow.

H_TeXMeX_H · 03-11-2009, 06:02 AM

I don't know, but I use the one in the '/extra' directory on the Slackware DVD.

H_TeXMeX_H · 03-12-2009, 11:09 AM

For an exact number FF 3 takes a little under 8 seconds to start.

Ilgar · 03-12-2009, 12:59 PM

Quote:

Originally Posted by ErV

Despite enabled dma I have impression that everything that accesses disk produces noticeable system-wide slowdown, which could explain slow start of applications. For example, here is ksysguard graph for "dd if=/dev/zero of=1.bin bs=1M count=2048".
Maybe something is "wrong" with ext3 mount options and can be improved?:

Aah, but isn't that the famous Linux I/O wait bug? Here is a Slashdot article and here is the Kernel bugzilla. It was introduced somewhere around 2.6.18 and is unresolved yet; but recently it gained some attention and is being actively worked on.

It may not necessarily be the cause of your problems, but it's likely. I haven't done any tests on my laptop, it has a slow 5400 RPM drive anyway, and I use LUKS encryption which causes some overhead. But still, I think my system suffers from this bug. My Firefox startup time is not that slow (should be like 8-10 secs) but heavy disk I/O like copying large files slows my system down terribly.

H_TeXMeX_H · 03-12-2009, 02:25 PM

So is this bug supposed to affect everyone ?

Quote:

Originally Posted by thomas.pi

Since 2.6.26/27 everyone should be affected by this issue.

As I'm running slamd64 12.1, my kernel version is 2.6.24.7 and I am NOT affected. Maybe try another kernel version, one before 2.6.26 ?

Ilgar · 03-12-2009, 02:54 PM

That's an early post by thomas.pi, those who have tried past versions seem to agree on 2.6.17 or 18 as the starting point. I've read much of that Bugzilla thread and the situation seems to be this: It's very hard to pinpoint what the cause is and it's even possible that there are several different bugs with the same symptoms. It's agreed that at least on some architectures/hardware/filesystems (and these are not so rare, btw) recent kernels are behaving significantly worse under high I/O load compared to earlier ones. They're still trying to find a test case that is uniformly reproducible. For some of the complaints the disk controllers were the likely causes, for some cases poor fysnc performance of ext3 is suspected. But quite a few people were able to reproduce this problem on different filesystems and hardware, so there probably is something wrong also with the scheduler (and if so, that should affect everyone). Using Deadline, Anticipatory or CFQ doesn't seem to make much difference. It's a mess really, as one of the kernel devs pointed out:

Quote:

Originally Posted by Jens Axboe

And to make a more general comment... This bug is impossible to solve, since it
(once again) has degraded into somewhere for everybody to tunnel everything
that relates to a system feeling sluggish...

...I'd LOVE to be able to look into this, but honestly I have no idea where to
start.

ErV · 03-12-2009, 06:57 PM

Quote:

Originally Posted by Ilgar

Aah, but isn't that the famous Linux I/O wait bug?

It is quite possible, because I experience slowdown during copying of large files. If it is it, then it is "great". Unresolved kernel bug is just what I needed.

I'll write again once I finally try to profile system with uncompressed vmlinux image.

H_TeXMeX_H · 03-13-2009, 04:23 AM

I say if that is the case try a different filesystem, it may be related to ext3. It seems other filesystems have less of an issue with this. ext4 also counts as possible solution.