Hi folks. I am running Slackware 10.2 and I've bee experiencing
latency issues with man pages for some time now (could be ever since it
was installed).

At the console (or an xterm) it takes 3 seconds for a man page to come
up and that is unacceptable. Yet the machine is responsive in every
other way.

Does anyone know where I should be looking to solve this problem?

--
Peter

On 2006-02-16, Peter <groups_for_google@yahoo.ca> wrote:
> Hi folks. I am running Slackware 10.2 and I've bee experiencing
> latency issues with man pages for some time now (could be ever since it
> was installed).
>
> At the console (or an xterm) it takes 3 seconds for a man page to come
> up and that is unacceptable. Yet the machine is responsive in every
> other way.
>
> Does anyone know where I should be looking to solve this problem?

Have you checked the man config file to make sure it's set properly, usually
/usr/lib/man.conf You may have issues here.

Is you pager working properly. Man pages are generally formatted and sent
to a pager, usually less.

Perhaps the manpath variable isn't set correctly...might cause a problem.

Also check to make sure the formatting engine is correctly set with the
right switches...ses man man for more info also see man man.conf

ken

"Peter" <groups_for_google@yahoo.ca> wrote:
> At the console (or an xterm) it takes 3 seconds for a man page to come
> up and that is unacceptable. Yet the machine is responsive in every
> other way.
>
> Does anyone know where I should be looking to solve this problem?

I would start by doing something like:

strace man ls

My guess is that strace will show you what man is waiting for. Maybe it is
waiting for a forked process, then you can do:

strace -f man ls

....to see what that forked process is waiting for.

regards Henrik
--
The address in the header is only to prevent spam. My real address is:
hc7(at)uthyres.com Examples of addresses which go to spammers:
root@variousus.net root@localhost

This is what I get for your first form:

execve("/usr/bin/man", ["man", "ls"], [/* 26 vars */]) = 0
uname({sys="Linux", node="marty.papamike.ca", ...}) = 0
brk(0) = 0x8058808
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or
directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=24221, ...}) = 0
mmap2(NULL, 24221, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40017000
close(3) = 0
open("/lib/libc.so.6", O_RDONLY) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\2 0U\1\000"...,
512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1340373, ...}) = 0
mmap2(NULL, 1150196, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3,
0) = 0x4001d000
mmap2(0x40130000, 16384, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x112) = 0x40130000
mmap2(0x40134000, 7412, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40134000
close(3) = 0
mprotect(0x40130000, 4096, PROT_READ) = 0
munmap(0x40017000, 24221) = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = -1
ENOENT (No such file or directory)
brk(0) = 0x8058808
brk(0x8079808) = 0x8079808
brk(0x807a000) = 0x807a000
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2586, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40017000
read(3, "# Locale name alias data base.\n#"..., 4096) = 2586
read(3, "", 4096) = 0
close(3) = 0
munmap(0x40017000, 4096) = 0
open("/usr/lib/locale/en_US/LC_CTYPE", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=178476, ...}) = 0
mmap2(NULL, 178476, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40136000
close(3) = 0
open("/usr/lib/locale/en_US/LC_MESSAGES", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFDIR|0755, st_size=80, ...}) = 0
close(3) = 0
open("/usr/lib/locale/en_US/LC_MESSAGES/SYS_LC_MESSAGES", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=57, ...}) = 0
mmap2(NULL, 57, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40017000
close(3) = 0
getuid32() = 0
geteuid32() = 0
getgid32() = 0
getegid32() = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
ioctl(0, TIOCGWINSZ, {ws_row=42, ws_col=138, ws_xpixel=0, ws_ypixel=0})
= 0
open("/usr/lib/man.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=4544, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40018000
read(3, "#\n# Generated automatically from"..., 4096) = 4096
brk(0x809b000) = 0x809b000
read(3, ":0p:tcl:n:l\n#\n# Default opti"..., 4096) = 448
read(3, "", 4096) = 0
stat64("/usr/local/man/en_US", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/local/man/en", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/local/man", {st_mode=S_IFDIR|0755, st_size=528, ...}) = 0
stat64("/usr/man/en_US", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/man/en", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/man", {st_mode=S_IFDIR|0755, st_size=1232, ...}) = 0
stat64("/usr/X11R6/man/en_US", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/X11R6/man/en", 0xbfff988c) = -1 ENOENT (No such file or
directory)
stat64("/usr/X11R6/man", {st_mode=S_IFDIR|0755, st_size=528, ...}) = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
open("/usr/local/man/man1/",
O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4
fstat64(4, {st_mode=S_IFDIR|0755, st_size=48, ...}) = 0
fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
getdents64(4, /* 2 entries */, 4096) = 48
getdents64(4, /* 0 entries */, 4096) = 0
close(4) = 0
open("/usr/local/man/man1/",
O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4
fstat64(4, {st_mode=S_IFDIR|0755, st_size=48, ...}) = 0
fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
getdents64(4, /* 2 entries */, 4096) = 48
getdents64(4, /* 0 entries */, 4096) = 0
close(4) = 0
open("/usr/man/man1/", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4
fstat64(4, {st_mode=S_IFDIR|0755, st_size=36816, ...}) = 0
fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
getdents64(4, /* 115 entries */, 4096) = 4096
getdents64(4, /* 112 entries */, 4096) = 4072
getdents64(4, /* 113 entries */, 4096) = 4064
getdents64(4, /* 115 entries */, 4096) = 4072
getdents64(4, /* 115 entries */, 4096) = 4072
getdents64(4, /* 114 entries */, 4096) = 4072
getdents64(4, /* 114 entries */, 4096) = 4096
getdents64(4, /* 113 entries */, 4096) = 4088
getdents64(4, /* 114 entries */, 4096) = 4096
getdents64(4, /* 114 entries */, 4096) = 4072
getdents64(4, /* 21 entries */, 4096) = 760
getdents64(4, /* 0 entries */, 4096) = 0
close(4) = 0
open("/usr/man/man1/", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY) = 4
fstat64(4, {st_mode=S_IFDIR|0755, st_size=36816, ...}) = 0
fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
getdents64(4, /* 115 entries */, 4096) = 4096
getdents64(4, /* 112 entries */, 4096) = 4072
getdents64(4, /* 113 entries */, 4096) = 4064
getdents64(4, /* 115 entries */, 4096) = 4072
getdents64(4, /* 115 entries */, 4096) = 4072
getdents64(4, /* 114 entries */, 4096) = 4072
getdents64(4, /* 114 entries */, 4096) = 4096
getdents64(4, /* 113 entries */, 4096) = 4088
getdents64(4, /* 114 entries */, 4096) = 4096
getdents64(4, /* 114 entries */, 4096) = 4072
getdents64(4, /* 21 entries */, 4096) = 760
getdents64(4, /* 0 entries */, 4096) = 0
close(4) = 0
access("/usr/man/man1/ls.1.gz", R_OK) = 0
access("/usr/man/man1/ls.1.gz", R_OK) = 0
pipe([4, 5]) = 0
fork() = 8681
close(5) = 0
fstat64(4, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40019000
read(4, ".\\\" Copyright Andries Brouwer, R"..., 4096) = 4096
close(4) = 0
waitpid(8681, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGPIPE}], 0) = 8681
--- SIGCHLD (Child exited) @ 0 (0) ---
munmap(0x40019000, 4096) = 0
ioctl(0, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo
....}) = 0
pipe([4, 5]) = 0
fork() = 8682
close(5) = 0
fstat64(4, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1,
0) = 0x40019000
read(4, ".\\\" Copyright Andries Brouwer, R"..., 4096) = 4096
close(4) = 0
waitpid(8682, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGPIPE}], 0) = 8682
--- SIGCHLD (Child exited) @ 0 (0) ---
munmap(0x40019000, 4096) = 0
rt_sigaction(SIGINT, {0x804e256, [INT], SA_RESTORER|SA_RESTART,
0x40045cb8}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGINT, {SIG_IGN}, {0x804e256, [INT],
SA_RESTORER|SA_RESTART, 0x40045cb8}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
fork() = 8683
waitpid(8683, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 8683
rt_sigaction(SIGINT, {0x804e256, [INT], SA_RESTORER|SA_RESTART,
0x40045cb8}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {SIG_DFL}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
rt_sigaction(SIGINT, {SIG_DFL}, {0x804e256, [INT],
SA_RESTORER|SA_RESTART, 0x40045cb8}, 8) = 0
exit_group(0) = ?



As for '-f' I get many lines like this:

[pid 8716] open("/usr/share/groff/site-font/devlatin1/DESC", O_RDONLY)
= -1 ENOENT (No such file or directory)

On 2006-02-16, Peter <groups_for_google@yahoo.ca> wrote:
> This is what I get for your first form:
>

If you're going to use strace and you're claiming a lag time in the display
of man pages you should thing about, also, running stace wwith the -c
option. this will get you a display of the time in each section of the
execution...

strace -c -o outputfilename.txt man ls or

strace -ttt -o outputfilename.txt man ls or

strace -tt -o outputfilename.txt man ls

ken

"Peter" <groups_for_google@yahoo.ca> wrote:
> This is what I get for your first form:
> execve("/usr/bin/man", ["man", "ls"], [/* 26 vars */]) = 0
....

The interesting part is not the complete log, but the interesting part is
what you are waiting for. Did you see the output from strace making a
pause? If so, the last line shown during the pause might explain what you
are waiting for.

> As for '-f' I get many lines like this:

> [pid 8716] open("/usr/share/groff/site-font/devlatin1/DESC", O_RDONLY)
> = -1 ENOENT (No such file or directory)

Do you get so many lines that it takes several seconds? Otherwise that is
probably not the problem.

regards Henrik
--
The address in the header is only to prevent spam. My real address is:
hc7(at)uthyres.com Examples of addresses which go to spammers:
root@variousus.net root@localhost

I have determined that the pause is proportional to the size of the man
page. 'man ls' takes about 1 second but 'man smb.conf' takes about 3
and 'man bash' is about 4. Applying strace does exhibit this pause
just prior to the page loading and then related info after I quit the
page:

munmap(0x40019000, 4096) = 0
rt_sigaction(SIGINT, {0x804e256, [INT], SA_RESTORER|SA_RESTART,
0x40045cb8}, {SIG_DFL}, 8) = 0
rt_sigaction(SIGINT, {SIG_IGN}, {0x804e256, [INT],
SA_RESTORER|SA_RESTART, 0x40045cb8}, 8) = 0
rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
fork 9661

{ man page appears and I quit }

[{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 9661
rt_sigaction(SIGINT, {0x804e256, [INT], SA_RESTORER|SA_RESTART,
0x40045cb8}, NULL, 8) = 0
rt_sigaction(SIGQUIT, {SIG_DFL}, NULL, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
rt_sigaction(SIGINT, {SIG_DFL}, {0x804e256, [INT],
SA_RESTORER|SA_RESTART, 0x40045cb8}, 8) = 0
exit_group(0) = ?

I'm following up on your lead:

$ strace -f man bash 2>&1 | grep fork
fork(Process 9910 attached (waiting for parent)
fork(Process 9911 attached (waiting for parent)
fork(Process 9912 attached (waiting for parent)
[pid 9912] fork(Process 9913 attached
[pid 9913] fork(Process 9914 attached
[pid 9914] fork( <unfinished ...>
[pid 9914] <... fork resumed> ) = 9915
[pid 9913] fork(Process 9916 attached
[pid 9913] fork( <unfinished ...>
[pid 9913] <... fork resumed> ) = 9917
[pid 9913] fork( <unfinished ...>
[pid 9913] <... fork resumed> ) = 9918
[pid 9917] fork(Process 9919 attached
[pid 9919] fork(Process 9920 attached
[pid 9917] fork(Process 9921 attached (waiting for parent)
[pid 9921] fork(Process 9922 attached
[pid 9921] fork( <unfinished ...>
[pid 9921] <... fork resumed> ) = 9923

On another xterm I was able to capture these processes:

9907 pts/1 S+ 0:00 strace -f man bash
9908 pts/1 S+ 0:00 grep fork
9909 pts/1 T+ 0:00 man bash
9912 pts/1 T+ 0:00 sh -c (cd /usr/man && (echo ".pl 11i";
/bin/gunzip -c '/usr/man/man1/bash.1.gz') | /usr/bin/gtbl | /usr/bin/n
9913 pts/1 T+ 0:00 sh -c (cd /usr/man && (echo ".pl 11i";
/bin/gunzip -c '/usr/man/man1/bash.1.gz') | /usr/bin/gtbl | /usr/bin/n
9916 pts/1 S+ 0:00 /usr/bin/gtbl
9917 pts/1 T+ 0:00 /bin/sh /usr/bin/nroff -Tlatin1 -mandoc
9918 pts/1 S+ 0:00 /usr/bin/less -is
9921 pts/1 T+ 0:00 groff -mtty-char -Tlatin1 -mandoc
9922 pts/1 R+ 0:02 troff -mtty-char -mandoc -Tlatin1
9923 pts/1 S+ 0:01 grotty

Process 9923 is the one that pauses. Anyone?

Peter <groups_for_google@yahoo.ca> wrote:
: 9907 pts/1 S+ 0:00 strace -f man bash
: 9908 pts/1 S+ 0:00 grep fork
: 9909 pts/1 T+ 0:00 man bash
: 9912 pts/1 T+ 0:00 sh -c (cd /usr/man && (echo ".pl 11i";
: /bin/gunzip -c '/usr/man/man1/bash.1.gz') | /usr/bin/gtbl | /usr/bin/n
: 9913 pts/1 T+ 0:00 sh -c (cd /usr/man && (echo ".pl 11i";
: /bin/gunzip -c '/usr/man/man1/bash.1.gz') | /usr/bin/gtbl | /usr/bin/n
: 9916 pts/1 S+ 0:00 /usr/bin/gtbl
: 9917 pts/1 T+ 0:00 /bin/sh /usr/bin/nroff -Tlatin1 -mandoc
: 9918 pts/1 S+ 0:00 /usr/bin/less -is
: 9921 pts/1 T+ 0:00 groff -mtty-char -Tlatin1 -mandoc
: 9922 pts/1 R+ 0:02 troff -mtty-char -mandoc -Tlatin1
: 9923 pts/1 S+ 0:01 grotty

: Process 9923 is the one that pauses. Anyone?

The delay seems to be stemming from the formatting of the man file. There
should be a way to cache the results of the first formatting to use for
all future man displays (along with an option to man to format but not
display a man file). This takes more disk-space, but if you have space to
spare and it's the delay that is bothering you, it is a potential solution.
There are also some potential security issues with caching man pages as
well. I would suggest giving it a good web search and decide if the delay
is annoying enough to warrant turning on caching.

"Peter" <groups_for_google@yahoo.ca> wrote:
> I have determined that the pause is proportional to the size of the man
> page. 'man ls' takes about 1 second but 'man smb.conf' takes about 3
> and 'man bash' is about 4. Applying strace does exhibit this pause
> just prior to the page loading and then related info after I quit the
> page:
>
> munmap(0x40019000, 4096) = 0
> rt_sigaction(SIGINT, {0x804e256, [INT], SA_RESTORER|SA_RESTART,
> 0x40045cb8}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGINT, {SIG_IGN}, {0x804e256, [INT],
> SA_RESTORER|SA_RESTART, 0x40045cb8}, 8) = 0
> rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
> fork 9661

If the pause comes here it explains what you are waiting for. The program
man has forked another process and is waiting for that child process to
complete. Now the next question is what is that child process up to that
takes so long time? Maybe that one is also waiting for something? Using
"strace -f" also reveals what the child processes are doing.

regards Henrik
--
The address in the header is only to prevent spam. My real address is:
hc7(at)uthyres.com Examples of addresses which go to spammers:
root@variousus.net root@localhost