Hello,
I am trying to troubleshoot an issue with a long delay while logging on to a Red Hat Linux 6.3 server.
The issue occurs even when I try to do a "su - meuser" from the box itself, which makes me think it may not be related to remote connectivity or network.
Anyways, I tried to use strace to find out what might be causing the delay. The strace output does show a particular call consuming 300 seconds to complete.
However, I am not sure what exactly it means.
Following are the relevant details:
1) strace -r -e trace=open,close,network,read,write -o sutrace.trc su - meuser
The relevant lines from sutrace.trc:
0.002662 socket(PF_FILE, SOCK_STREAM, 0) = 5
0.000471 connect(5, {sa_family=AF_FILE, path="/var/lib/sss/pipes/pam"}, 110) = 0
0.003306 write(5, "\24\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
0.000445 write(5, "\3\0\0\0", 4) = 4
0.000236 read(5, "\24\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
0.000278 read(5, "\3\0\0\0", 4) = 4
0.000237 getsockopt(5, SOL_SOCKET, SO_PEERCRED, "\5\7\0\0\0\0\0\0\0\0\0\0", [12]) = 0
0.000229 write(5, "]\0\0\0\364\0\0\0\0\0\0\0\0\0\0\0", 16) = 16
0.000234 write(5, "IPAM\1\0\0\0\7\0\0\0oracle\0\2\0\0\0\5\0\0\0su-l\0"..., 77) = 77
300.059967 close(5) = 0
2) strace -r -e trace=open,close,network,read,write -o sshtrace.trc ssh meuser@localserver
The relevant lines from sutrace.trc:
0.000295 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
.
.
.
300.951476 read(3, "b\343\205\370UI\376dq\244!I\6\214\203\301\205\354\323k\26\212\347\246t@\243\rpL\353\341"..., 8192) = 48
3) strace -c ssh meuser@localserver
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
37.04 0.001222 5 251 182 open
30.31 0.001000 24 42 select
12.76 0.000421 14 31 write
7.79 0.000257 11 24 15 stat
3.36 0.000111 1 88 close
2.76 0.000091 2 53 fstat
2.24 0.000074 1 132 read
1.97 0.000065 3 23 munmap
1.76 0.000058 1 41 rt_sigaction
0.00 0.000000 0 5 poll
0.00 0.000000 0 95 mmap
0.00 0.000000 0 52 mprotect
0.00 0.000000 0 6 brk
0.00 0.000000 0 1 rt_sigprocmask
0.00 0.000000 0 17 ioctl
0.00 0.000000 0 1 1 access
0.00 0.000000 0 3 dup
0.00 0.000000 0 16 socket
0.00 0.000000 0 9 6 connect
0.00 0.000000 0 9 sendto
0.00 0.000000 0 2 recvfrom
0.00 0.000000 0 14 recvmsg
0.00 0.000000 0 1 shutdown
0.00 0.000000 0 7 bind
0.00 0.000000 0 8 getsockname
0.00 0.000000 0 1 getpeername
0.00 0.000000 0 3 setsockopt
0.00 0.000000 0 2 getsockopt
0.00 0.000000 0 1 execve
0.00 0.000000 0 1 uname
0.00 0.000000 0 15 fcntl
0.00 0.000000 0 1 umask
0.00 0.000000 0 1 getrlimit
0.00 0.000000 0 2 getuid
0.00 0.000000 0 1 geteuid
0.00 0.000000 0 1 setresuid
0.00 0.000000 0 1 statfs
0.00 0.000000 0 1 arch_prctl
0.00 0.000000 0 9 1 futex
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.003299 973 205 total
Can you please help me understand what exactly does "socket(PF_FILE, SOCK_STREAM, 0)" do?
In the above output, I am assuming that the calls taking most time are for the operations corresponding to this "socket" entry.
I am no linux expert so can't really understand how to interpret this?
Thanks in advance.