linux 에서 Salt 명령 을 내 리 는 난치병

http://hushi55.github.io/2015/01/22/linux-strace
머리말
오늘 운영 동료 가 사용 하고 있 습 니 다.

salt '*' test.ping

두 기계 의 집행 시간 은 완전히 다르다.정상 적 인 것 은:

[root@salt_master ~]# time salt-key -L
Accepted Keys:
213
217
minion213
Unaccepted Keys:
Rejected Keys:

real    0m1.210s
user    0m0.732s
sys     0m0.339s

비정상적인 실행 시간 은:

[root@salt_master ~]# time salt-key -L
Accepted Keys:
213
217
minion213
Unaccepted Keys:
Rejected Keys:

real    0m41.134s
user    0m0.761s
sys     0m0.318s

차이 가 너무 커서 받 아들 일 수 없 으 니 원인 을 찾 아야 한다.이런 어 려 운 문제 에 부 딪 히 면 strace 가 도움 이 된다.
strace 사용 설명
일단 스 트 라 이 스 사용법 을 살 펴 보도 록 하 겠 습 니 다.

[root@perf01 ~]# strace --help
strace: invalid option -- '-'
usage: strace [-dDffhiqrtttTvVxx] [-a column] [-e expr] ... [-o file]
              [-p pid] ... [-s strsize] [-u username] [-E var=val] ...
              [command [arg ...]]
   or: strace -c [-D] [-e expr] ... [-O overhead] [-S sortby] [-E var=val] ...
              [command [arg ...]]
-c -- count time, calls, and errors for each syscall and report summary
-f -- follow forks, -ff -- with output into separate files
-F -- attempt to follow vforks, -h -- print help message
-i -- print instruction pointer at time of syscall
-q -- suppress messages about attaching, detaching, etc.
-r -- print relative timestamp, -t -- absolute timestamp, -tt -- with usecs
-T -- print time spent in each syscall, -V -- print version
-v -- verbose mode: print unabbreviated argv, stat, termio[s], etc. args
-x -- print non-ascii strings in hex, -xx -- print all strings in hex
-a column -- alignment COLUMN for printing syscall results (default 40)
-e expr -- a qualifying expression: option=[!]all or option=[!]val1[,val2]...
   options: trace, abbrev, verbose, raw, signal, read, or write
-o file -- send trace output to FILE instead of stderr
-O overhead -- set overhead for tracing syscalls to OVERHEAD usecs
-p pid -- trace process with process id PID, may be repeated
-D -- run tracer process as a detached grandchild, not as parent
-s strsize -- limit length of print strings to STRSIZE chars (default 32)
-S sortby -- sort syscall counts by: time, calls, name, nothing (default time)
-u username -- run command as username handling setuid and/or setgid
-E var=val -- put var=val in the environment for command
-E var -- remove var from the environment for command
[root@perf01 ~]#

오늘 우리 가 만난 문제 에 대해 우 리 는 아래 의 매개 변 수 를 중점적으로 주목한다.

- f: fork 를 포함 한 하위 프로 세 스 를 추적 합 니 다.

- o file: 표준 출력 흐름 이 아 닌 출력 추적 로 그 를 파일 에 출력 합 니 다.

- T: 인쇄 시스템 호출 시간.

strace 사용
우 리 는 아래 명령 을 사용한다.

strace -f -T -o aa.txt salt '*' test.ping

우리 가 얻 은 텍스트 파일 을 엑셀 에 복사 하여 <, > 에 따라 열 을 나 누 어 시스템 호출 시간 을 한 열 에 두 고 엑셀 의 정렬 기능 을 사용 하여 내림차 순 으로 배열 하면 우 리 는 아래 의 것 을 볼 수 있다.

4669  poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout)  5.005197
4669  poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout)  5.005197
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004221
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004221
4669  poll([{fd=4, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004206
4669  poll([{fd=4, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004206
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004201
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004201
4669  poll([{fd=4, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.00418
4669  poll([{fd=4, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.00418
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004177
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004177
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004166
4669  poll([{fd=3, events=POLLIN}], 1, 4999) = 0 (Timeout)  5.004166
4669  select(0, NULL, NULL, NULL, {0, 25000}) = 0 (Timeout)     0.025196
4669  select(0, NULL, NULL, NULL, {0, 25000}) = 0 (Timeout)     0.025196
4669  select(0, NULL, NULL, NULL, {0, 25000}) = 0 (Timeout)     0.025184
4669  select(0, NULL, NULL, NULL, {0, 25000}) = 0 (Timeout)     0.025184

poll 시스템 호출 에 대량의 시간 초과 가 존재 하 는 것 을 발 견 했 습 니 다. 우 리 는 지금 그 중 하 나 를 복사 할 수 있 습 니 다.

4669  poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout)

aa. txt 에서 이 호출 된 컨 텍스트 를 찾 습 니 다.

4669  connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("202.96.199.133")}, 16) = 0 <0.000048>
4669  gettimeofday({1421912262, 387646}, NULL) = 0 <0.000038>
4669  poll([{fd=3, events=POLLOUT}], 1, 0) = 1 ([{fd=3, revents=POLLOUT}]) <0.000047>
4669  sendto(3, "K`\1\0\0\1\0\0\0\0\0\0\00234\003199\003106\003202\7in-a"..., 45, MSG_NOSIGNAL, NULL, 0) = 45 <0.000057>
4669  poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout) <5.005197>
4669  socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 4 <0.000059>
4669  connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("202.106.196.115")}, 16) = 0 <0.000051>
4669  gettimeofday({1421912267, 394615}, NULL) = 0 <0.000037>

링크 가 연 결 된 ip 주 소 를 볼 수 있 습 니 다.

...
... sin_addr=inet_addr("202.96.199.133")
...
... sin_addr=inet_addr("202.106.196.115")

이 두 ip 주 소 는 이 Liux 에 설 치 된 DNS 입 니 다. 호스트 에 ping 이라는 두 주 소 는 확실히 ping 이 통 하지 않 습 니 다. 정상 적 인 Liux 의 DNS 설정 에 비해 설정 이 확실히 다 릅 니 다.일치 하도록 수정 한 후 문제 가 사 라 졌 다.이로써 strace 디 버 깅 문 제 를 사용 하 는 것 도 완벽 하 게 끝났다.
레 퍼 런 스

http://www.ibm.com/developerworks/cn/linux/l-tsl/