10.1: Extreme slow startup of acroread
Hello Since upgrading my system (1.8GHz P4 with 512MB RAM and Ultra 160 SCSI drives), the startup time of some programs (most particularly, acrobat reader) have gotten REALLY long. For instance, it takes a minute and 4 seconds for the acroread window to appear on the display after typing "/usr/bin/acroread" at a shell prompt. $ time acroread real 1m4.604s user 1m1.764s sys 0m1.144s When I was running 10.0 I never measured the startup time because it was very quick, but I would estimate it used to take 5 seconds max to start up. I have run strace on it under 10.1, and the summary shows this in the first few lines: % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 45.68 0.087192 632 138 65 waitpid 14.09 0.026892 1 24464 425 read 10.42 0.019895 1 19085 17566 open 10.20 0.019469 87 224 madvise 4.81 0.009182 214 43 execve 2.37 0.004527 17 262 getdents64 2.21 0.004210 4 1020 510 access 2.14 0.004081 2 1932 296 stat64 2.10 0.003999 3 1476 poll 1.40 0.002667 6 477 munmap 1.24 0.002373 47 50 writev 0.99 0.001894 1 2700 write 0.60 0.001139 3 391 _llseek 0.00 0.000000 0 2 shmctl ... many lines deleted... ------ ----------- ----------- --------- --------- ---------------- 100.00 0.190871 73318 18980 total It seems to be spending over 45% of the time on waitpid syscalls, and it also did over 19,000 open calls of which about 92% resulted in failure. I thought I might have a bad LD_LIBRARY_PATH, but it is not set in either my or root's environment. There was some cruft in /etc/ld.so.conf, but I removed that and it didn't make any difference. When I look at the detailed tracelog I can see that the vast majority of open calls result in ENOENT (no such file or directory) or EACCES (Permission denied). Most are ENOENT though, because it seems to be looking for stuff where it isn't... thousands and thousands of times. I can even see instances where it did a STAT on the file and the STAT failed, then it immediately tried to open the file in the same location, which naturally failed too. I thought it might have something to do with my environment as a particular user, so I tried it as root (same problem) and even created a brand new virgin user and that account sees the same problem. Any ideas on how to troubleshoot and fix this? Oh, I also tried removing the SuSE-supplied acrobat rpm and replacing it with the one from the Adobe site... no improvement. Thanks in advance for any help and / or suggestions! Michael --- San Francisco, CA
My investigations continue... in analyzing the tracelog, I see 5777 instances of opens trying to open things that are clearly NOT directories while using the O_DIRECTORY flag on the open: open("/usr/X11R6/lib/X11/fonts/CID/encodings.dir", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = -1 ENOTDIR (Not a directory) <0.000021> I am over my head here, but I did read in the open(2) man page the following: O_DIRECTORY If pathname is not a directory, cause the open to fail. This flag is Linux-specific, and was added in kernel version 2.1.126, to avoid denial-of-service problems if opendir(3) is called on a FIFO or tape device, but should not be used outside of the implementation of opendir. ...so, it looks to this non programmer that they shouldn't be using the O_DIRECTORY flag on an open() call, but what do I know? I'm just trying to figure out why it takes this thing so long to open. Michael -- San Francisco, CA
Michael Nelson wrote:
My investigations continue... in analyzing the tracelog, I see 5777 instances of opens trying to open things that are clearly NOT directories while using the O_DIRECTORY flag on the open:
open("/usr/X11R6/lib/X11/fonts/CID/encodings.dir", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = -1 ENOTDIR (Not a directory) <0.000021>
I am over my head here, but I did read in the open(2) man page the following:
O_DIRECTORY If pathname is not a directory, cause the open to fail. This flag is Linux-specific, and was added in kernel version 2.1.126, to avoid denial-of-service problems if opendir(3) is called on a FIFO or tape device, but should not be used outside of the implementation of opendir.
...so, it looks to this non programmer that they shouldn't be using the O_DIRECTORY flag on an open() call, but what do I know? I'm just trying to figure out why it takes this thing so long to open.
Michael
Hi Michael, can you check that YaST Software Management doesn't report missing dependencies. If not than you might look http://bugzilla.novell.com and report the bug. -- Regards, Rajko.
On Sun, May 28, 2006 at 07:37:59AM -0500, Rajko M wrote:
can you check that YaST Software Management doesn't report missing dependencies.
I have, and it doesn't. I will file a bug if it turns out it isn't something I have misconfigured on my system, but I want to rule that out first. Any strace experts here who would like to take a look at the tracelog? wget http://home.comcast.net/~michaelnel/acroread_traces.tar.gz will get you your very own copy! ;-) Thanks Michael -- San Francisco, CA
On Sun, May 28, 2006 at 07:37:59AM -0500, Rajko M wrote:
If not than you might look http://bugzilla.novell.com and report the bug.
Aaarrggghhh. I should have looked there earlier, I had assumed this was something I had screwed up, but "Bug 147966 - acroread takes long time to start" looks like the same issue: https://bugzilla.novell.com/show_bug.cgi?id=147966 I'll play with the workarounds noted in that as yet unfixed CRITICAL bug. Michael -- San Francisco, CA
On Sun, May 28, 2006 at 06:35:24AM -0700, Michael Nelson wrote:
Aaarrggghhh. I should have looked there earlier, I had assumed this was something I had screwed up, but "Bug 147966 - acroread takes long time to start" looks like the same issue:
https://bugzilla.novell.com/show_bug.cgi?id=147966
I'll play with the workarounds noted in that as yet unfixed CRITICAL bug.
OK, I'm a dummy. Somewhere along the line I had installed Adobe's AdobeReader package. The startup script for that is /usr/bin/acroread. The startup script for the SuSE supplied one is /usr/X11R6/bin/acroread, which is *after* /usr/bin in my $PATH. So all this time I have been running and troubleshooting the Adobe version instead of the SuSE version. The SuSE version does have a fix in it for bug 147966, and it starts MUCH faster. I do still see some inefficiencies in the tracelog though, even with the SuSE startup script. For instance, initially the script finds libc.so.6 right away in /lib, which is where it is and where a program should be looking for it. But after a while it loses its mind and does this: 3264 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000020> 3264 open("/opt/gnome/lib/tls/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.00 0041> 3264 open("/opt/gnome/lib/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.00001 7> 3264 open("/opt/gnome/lib/tls/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000023
3264 open("/opt/gnome/lib/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000021> 3264 open("/opt/gnome/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000024> 3264 open("/lib/tls/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000027> 3264 open("/lib/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/tls/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000020> 3264 open("/lib/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000015> 3264 open("/lib/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000021> 3264 open("/lib/libc.so.6", O_RDONLY) = 3 <0.000020> ...then, for the rest of the trace log it follows that same screwy pattern every time it wants to access libc.so.6, and that *has* to be slowing things down. Michael -- San Francisco, CA
Michael Nelson wrote:
On Sun, May 28, 2006 at 06:35:24AM -0700, Michael Nelson wrote:
Aaarrggghhh. I should have looked there earlier, I had assumed this was something I had screwed up, but "Bug 147966 - acroread takes long time to start" looks like the same issue:
https://bugzilla.novell.com/show_bug.cgi?id=147966
I'll play with the workarounds noted in that as yet unfixed CRITICAL bug.
OK, I'm a dummy.
Somewhere along the line I had installed Adobe's AdobeReader package. The startup script for that is /usr/bin/acroread. The startup script for the SuSE supplied one is /usr/X11R6/bin/acroread, which is *after* /usr/bin in my $PATH. So all this time I have been running and troubleshooting the Adobe version instead of the SuSE version.
The SuSE version does have a fix in it for bug 147966, and it starts MUCH faster.
I do still see some inefficiencies in the tracelog though, even with the SuSE startup script. For instance, initially the script finds libc.so.6 right away in /lib, which is where it is and where a program should be looking for it. But after a while it loses its mind and does this:
3264 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) <0.000020> 3264 open("/opt/gnome/lib/tls/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.00 0041> 3264 open("/opt/gnome/lib/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.00001 7> 3264 open("/opt/gnome/lib/tls/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000023 3264 open("/opt/gnome/lib/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016> 3264 open("/opt/gnome/lib/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000021> 3264 open("/opt/gnome/lib/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000024> 3264 open("/lib/tls/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000027> 3264 open("/lib/tls/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/tls/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/tls/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000014> 3264 open("/lib/i686/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000020> 3264 open("/lib/i686/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000015> 3264 open("/lib/tm/libc.so.6", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000021> 3264 open("/lib/libc.so.6", O_RDONLY) = 3 <0.000020>
...then, for the rest of the trace log it follows that same screwy pattern every time it wants to access libc.so.6, and that *has* to be slowing things down.
Michael
I was looking for "acrobat" on bugzilla and it returned one unrelated bug. I can see your observations added to the bug #147966. It will probably bring more light in. -- Regards, Rajko.
On Sun, May 28, 2006 at 10:02:18AM -0500, Rajko M wrote:
I can see your observations added to the bug #147966. It will probably bring more light in.
I spoke too soon. I ran /usr/X11R6/bin/acroread once and it started up in 8 seconds. On every subsequent attempt it takes over a minute to start, so the fixes are NOT working on my system. I am continuing to analyze the trace file and finding LOTS of stuff that looks wrong to me, but I don't really understand this stuff that well. I hope someone who does can look at the tracelogs. I've put new ones out at wget http://home.comcast.net/~michaelnel/acroread_traces.tar.gz Thanks Michael -- San Francisco, CA
Michael Nelson wrote:
Hello
Since upgrading my system (1.8GHz P4 with 512MB RAM and Ultra 160 SCSI drives), the startup time of some programs (most particularly, acrobat reader) have gotten REALLY long.
For instance, it takes a minute and 4 seconds for the acroread window to appear on the display after typing "/usr/bin/acroread" at a shell prompt.
Do you need to run acrobat? Why not use xpdf, which does a faster open and looks just as well? Adam in NYC with SuSE 10.0
On Sun, May 28, 2006 at 07:34:52AM -0400, Adam Vazquez Kb2jpd wrote:
Do you need to run acrobat? Why not use xpdf, which does a faster open and looks just as well?
Yes, I can run xpdf, and yes, it starts up in a few seconds. But I would prefer to use acrobat instead, as it has features I like to use that are not present in xpdf. Besides, acrobat used to work well, and I want to know why it no longer does. Thanks though. Michael -- San Francisco, CA
participants (3)
-
Adam Vazquez Kb2jpd -
Michael Nelson -
Rajko M