strace解决ssh登陆缓慢

Linux 诊断工具strace使用案例
一：strace常用参数说明:
-p 跟踪的进程号
-f            Trace child processes as they are created by currently traced processes as a result of the fork(2) system call.

跟踪当前进程创建的子进程
-F          This option is now obsolete and it has the same functionality as -f
-F    尝试跟踪vfork子进程系统调吸入，与-f同时出现时, vfork不被跟踪


-o    filename 默认strace将结果输出到stdout。通过-o可以将输出写入到filename文件中

-T          Show the time spent in system calls. 
      strace可以使用参数-T将每个系统调用所花费的时间打印出来，每个调用的时间花销现在在调用行最右边的尖括号里面。

二:strace 使用:
为了模拟ssh 登陆缓慢,配置了DNS:
[root@june2 ~]# cat /etc/resolv.conf 
;generated by /sbin/dhclient-script
nameserver 9.8.7.6
serch nameserver

[root@june2 ~]# ps -ef | grep  sshd | grep -v grep
root      1978     1  0 07:06 ?        00:00:00 /usr/sbin/sshd
root     28838  1978  0 10:54 ?        00:00:01 sshd: root@pts/0 
root     30223  1978  0 12:01 ?        00:00:00 sshd: root@pts/1 
root     30261 28840  0 12:02 pts/0    00:00:00 vi sshd.strace

我们先strace -o sshd.strace -fT -p 1978  跟踪 /usr/sbin/sshd进程,然后打开新的窗口登陆,可以看到如下输出:
 open("/etc/resolv.conf", O_RDONLY) = 4 <0.000013>
30223 fstat64(4, {st_mode=S_IFREG|0644, st_size=685, ...}) = 0 <0.000010>
30223 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f97000 <0.000011>
30223 read(4, "; generated by /sbin/dhclient-sc"..., 4096) = 685 <0.000022>
30223 read(4, "", 4096)                 = 0 <0.000010>
30223 close(4)                          = 0 <0.000010>
30223 munmap(0xb7f97000, 4096)          = 0 <0.000013>
30223 uname({sys="Linux", node="june2", ...}) = 0 <0.000090>
30223 open("/etc/host.conf", O_RDONLY)  = 4 <0.000013>
30223 fstat64(4, {st_mode=S_IFREG|0644, st_size=17, ...}) = 0 <0.000010>
30223 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f97000 <0.000011>
30223 read(4, "order hosts,bind
", 4096) = 17 <0.000018>
30223 read(4, "", 4096)                 = 0 <0.000010>
30223 close(4)                          = 0 <0.000010>
30223 munmap(0xb7f97000, 4096)          = 0 <0.000013>
30223 futex(0xd2d804, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000009>
30223 open("/etc/hosts", O_RDONLY)      = 4 <0.000019>
30223 fcntl64(4, F_GETFD)               = 0 <0.000009>
30223 fcntl64(4, F_SETFD, FD_CLOEXEC)   = 0 <0.000010>
30223 fstat64(4, {st_mode=S_IFREG|0644, st_size=216, ...}) = 0 <0.000009>
30223 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f97000 <0.000011>
30223 read(4, "# Do not remove the following li"..., 4096) = 216 <0.000016>
30223 read(4, "", 4096)                 = 0 <0.000010>
30223 close(4)                          = 0 <0.000010>
30223 munmap(0xb7f97000, 4096)          = 0 <0.000014>
30223 open("/etc/ld.so.cache", O_RDONLY) = 4 <0.000012>
30223 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 7 <0.000022>
30223 connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("9.8.7.6")}, 28) = 0 <0.000016>
30223 fcntl64(7, F_GETFL)               = 0x2 (flags O_RDWR) <0.000012>
30223 fcntl64(7, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000012>
30223 gettimeofday({1406260903, 647862}, NULL) = 0 <0.000010>
30223 poll([{fd=7, events=POLLOUT}], 1, 0) = 1 ([{fd=7, revents=POLLOUT}]) <0.000011>
30223 send(7, "225271110110217021002107in-addr4"..., 41, MSG_NOSIGNAL) = 41 <0.000177>
30223 poll([{fd=7, events=POLLIN}], 1, 3000) = 0 (Timeout) <3.000668>
30223 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8 <0.000017>
30223 connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("9.8.7.6")}, 28) = 0 <0.000016>
30223 fcntl64(8, F_GETFL)               = 0x2 (flags O_RDWR) <0.000011>
30223 fcntl64(8, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000011>
30223 gettimeofday({1406260906, 649181}, NULL) = 0 <0.000011>
30223 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}]) <0.000012>
30223 send(8, "225271110110217021002107in-addr4"..., 41, MSG_NOSIGNAL) = 41 <0.000194>
30223 poll([{fd=8, events=POLLIN}], 1, 6000) = 0 (Timeout) <6.000321>
30223 gettimeofday({1406260912, 649917}, NULL) = 0 <0.000012>
30223 poll([{fd=4, events=POLLOUT}], 1, 0) = 1 ([{fd=4, revents=POLLOUT}]) <0.000012>
30223 send(4, "225271110110217021002107in-addr4"..., 41, MSG_NOSIGNAL) = 41 <0.000186>
30223 poll([{fd=4, events=POLLIN}], 1, 5000) = 0 (Timeout) <5.000118>
30223 gettimeofday({1406260917, 650463}, NULL) = 0 <0.000011>
30223 poll([{fd=7, events=POLLOUT}], 1, 0) = 1 ([{fd=7, revents=POLLOUT}]) <0.000011>
30223 send(7, "225271110110217021002107in-addr4"..., 41, MSG_NOSIGNAL) = 41 <0.000175>
30223 poll([{fd=7, events=POLLIN}], 1, 3000) = 0 (Timeout) <3.000386>
30223 gettimeofday({1406260920, 651220}, NULL) = 0 <0.000012>
30223 poll([{fd=8, events=POLLOUT}], 1, 0) = 1 ([{fd=8, revents=POLLOUT}]) <0.000012>
30223 send(8, "225271110110217021002107in-addr4"..., 41, MSG_NOSIGNAL) = 41 <0.000194>
30223 poll([{fd=8, events=POLLIN}], 1, 6000) = 0 (Timeout) <6.000294>

通过红色部分,我们可以看到：
 connect(7, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("9.8.7.6")}, 28) = 0 <0.000016>

开始连接到DNS，这点可以从sin_port=htons(53)输出可以看出,建立socket连接。

30223 poll([{fd=7, events=POLLIN}], 1, 3000) = 0 (Timeout) <3.000668>

然后调用poll函数，每个poll调用5s后超时返回

Poll 函数作用:
it waits for one of a set of file descriptors to become ready to perform I/O

POLLIN  There is data to read

大概意识就是等待从文件句柄中读入data,等待<3.000668>后超时