top최근에 or 와 같은 명령을 서버에서 실행할 때 ps -aux결과(STDOUT)가 매우 느리게 표시되는 것을 발견했습니다. 디스크 공간, 메모리, CPU 사용량을 확인했는데 모든 것이 정상입니다.
온라인에서 일부 정보를 읽은 후 명령도 실행했습니다 strace -o strace_report.txt top. 하지만 저는 보고서 내용을 이해하지 못했고, 보고서에서 어떤 문제점도 발견하지 못했습니다. top문제의 서버에서는 프로그램이 실행되는 데 24초가 걸리지만, 다른 서버에서는 2초밖에 걸리지 않습니다.
top해당 서버에서 명령을 실행하는 데 걸린 시간입니다.
real 0m23.988s
user 0m0.023s
sys 0m0.025s
top일반 서버에서 명령이 실행되는 시간입니다.
real 0m2.462s
user 0m0.017s
sys 0m0.011s
이상하게도 모든 명령이 느린 것은 아닙니다. 또한 ls즉시 출력을 얻는 등의 명령을 테스트했습니다 .
문제가 어디에 있는지 알아내는 방법을 가르쳐 줄 수 있는 사람이 있습니까?
@berndbausch의 제안에 따라 strace출력을 다음과 같이 요약했습니다.통계자료.
출력의 의미를 잘 모르겠습니다 strace. 문제가 다음에서 발생하는지 확인하는 데 도움을 줄 수 있는 사람이 있습니까?여론조사?
geteuid
num calls: 1 0% of syscalls
tot time: 0.000004 0% of syscall time, 0% of wall time
avg call time: 0.000004
+/-: 0.000000
med call time: 0.000004
min/hist/max: 0.000004 [0 0 0 0 1 0 0 0 0 0] 0.000004
dup
num calls: 1 0% of syscalls
tot time: 0.000005 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000000
med call time: 0.000005
min/hist/max: 0.000005 [0 0 0 0 0 1 0 0 0 0] 0.000005
set_tid_address
num calls: 1 0% of syscalls
tot time: 0.000005 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000000
med call time: 0.000005
min/hist/max: 0.000005 [0 0 0 0 0 1 0 0 0 0] 0.000005
futex
num calls: 1 0% of syscalls
tot time: 0.000005 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000000
med call time: 0.000005
min/hist/max: 0.000005 [0 0 0 0 0 1 0 0 0 0] 0.000005
getsockname
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
arch_prctl
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
getpid
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
dup3
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
set_robust_list
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
prlimit64
num calls: 1 0% of syscalls
tot time: 0.000006 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000000
med call time: 0.000006
min/hist/max: 0.000006 [0 0 0 0 1 0 0 0 0 0] 0.000006
sched_getaffinity
num calls: 1 0% of syscalls
tot time: 0.000007 0% of syscall time, 0% of wall time
avg call time: 0.000007
+/-: 0.000000
med call time: 0.000007
min/hist/max: 0.000007 [0 0 0 0 0 1 0 0 0 0] 0.000007
gettid
num calls: 1 0% of syscalls
tot time: 0.000008 0% of syscall time, 0% of wall time
avg call time: 0.000008
+/-: 0.000000
med call time: 0.000008
min/hist/max: 0.000008 [0 0 0 0 1 0 0 0 0 0] 0.000008
getuid
num calls: 1 0% of syscalls
tot time: 0.000008 0% of syscall time, 0% of wall time
avg call time: 0.000008
+/-: 0.000000
med call time: 0.000008
min/hist/max: 0.000008 [0 0 0 0 1 0 0 0 0 0] 0.000008
getrandom
num calls: 1 0% of syscalls
tot time: 0.000012 0% of syscall time, 0% of wall time
avg call time: 0.000012
+/-: 0.000000
med call time: 0.000012
min/hist/max: 0.000012 [0 0 0 0 1 0 0 0 0 0] 0.000012
sysinfo
num calls: 1 0% of syscalls
tot time: 0.000013 0% of syscall time, 0% of wall time
avg call time: 0.000013
+/-: 0.000000
med call time: 0.000013
min/hist/max: 0.000013 [0 0 0 0 0 1 0 0 0 0] 0.000013
dup2
num calls: 1 0% of syscalls
tot time: 0.000016 0% of syscall time, 0% of wall time
avg call time: 0.000016
+/-: 0.000000
med call time: 0.000016
min/hist/max: 0.000016 [0 0 0 0 1 0 0 0 0 0] 0.000016
setsockopt
num calls: 4 0% of syscalls
tot time: 0.000026 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000001
med call time: 0.000006
min/hist/max: 0.000006 [3 0 0 0 0 0 0 0 0 1] 0.000008
socket
num calls: 3 0% of syscalls
tot time: 0.000035 0% of syscall time, 0% of wall time
avg call time: 0.000012
+/-: 0.000003
med call time: 0.000013
min/hist/max: 0.000007 [1 0 0 0 0 0 0 1 0 1] 0.000015
getsockopt
num calls: 6 0% of syscalls
tot time: 0.000046 0% of syscall time, 0% of wall time
avg call time: 0.000008
+/-: 0.000002
med call time: 0.000007
min/hist/max: 0.000006 [2 2 0 1 0 0 0 0 0 1] 0.000012
connect
num calls: 3 0% of syscalls
tot time: 0.000047 0% of syscall time, 0% of wall time
avg call time: 0.000016
+/-: 0.000006
med call time: 0.000016
min/hist/max: 0.000008 [1 0 0 0 0 1 0 0 0 1] 0.000023
sendmsg
num calls: 3 0% of syscalls
tot time: 0.000048 0% of syscall time, 0% of wall time
avg call time: 0.000016
+/-: 0.000005
med call time: 0.000016
min/hist/max: 0.000010 [1 0 0 0 1 0 0 0 0 1] 0.000022
rt_sigprocmask
num calls: 3 0% of syscalls
tot time: 0.000060 0% of syscall time, 0% of wall time
avg call time: 0.000020
+/-: 0.000015
med call time: 0.000014
min/hist/max: 0.000006 [1 0 1 0 0 0 0 0 0 1] 0.000040
ioctl
num calls: 17 0% of syscalls
tot time: 0.000117 0% of syscall time, 0% of wall time
avg call time: 0.000007
+/-: 0.000002
med call time: 0.000006
min/hist/max: 0.000004 [1 5 3 3 0 0 3 1 0 1] 0.000012
brk
num calls: 12 0% of syscalls
tot time: 0.000120 0% of syscall time, 0% of wall time
avg call time: 0.000010
+/-: 0.000003
med call time: 0.000010
min/hist/max: 0.000005 [2 1 0 4 3 1 0 0 0 1] 0.000018
write
num calls: 7 0% of syscalls
tot time: 0.000159 0% of syscall time, 0% of wall time
avg call time: 0.000023
+/-: 0.000010
med call time: 0.000019
min/hist/max: 0.000009 [2 0 0 1 1 0 0 0 0 3] 0.000034
access
num calls: 22 0% of syscalls
tot time: 0.000190 0% of syscall time, 0% of wall time
avg call time: 0.000009
+/-: 0.000003
med call time: 0.000008
min/hist/max: 0.000006 [9 6 2 0 2 2 0 0 0 1] 0.000018
lseek
num calls: 38 0% of syscalls
tot time: 0.000222 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000001
med call time: 0.000006
min/hist/max: 0.000004 [ 4 14 10 8 1 0 0 0 0 1] 0.000012
execve
num calls: 1 0% of syscalls
tot time: 0.000238 0% of syscall time, 0% of wall time
avg call time: 0.000238
+/-: 0.000000
med call time: 0.000238
min/hist/max: 0.000238 [0 0 0 0 1 0 0 0 0 0] 0.000238
munmap
num calls: 21 0% of syscalls
tot time: 0.000280 0% of syscall time, 0% of wall time
avg call time: 0.000013
+/-: 0.000005
med call time: 0.000013
min/hist/max: 0.000006 [ 3 4 10 1 2 0 0 0 0 1] 0.000033
fcntl
num calls: 58 0% of syscalls
tot time: 0.000299 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000001
med call time: 0.000005
min/hist/max: 0.000004 [ 4 0 48 0 2 2 0 1 0 1] 0.000009
recvmsg
num calls: 9 0% of syscalls
tot time: 0.000302 0% of syscall time, 0% of wall time
avg call time: 0.000034
+/-: 0.000060
med call time: 0.000016
min/hist/max: 0.000006 [8 0 0 0 0 0 0 0 0 1] 0.000202
mprotect
num calls: 36 0% of syscalls
tot time: 0.000338 0% of syscall time, 0% of wall time
avg call time: 0.000009
+/-: 0.000003
med call time: 0.000008
min/hist/max: 0.000006 [ 3 5 13 0 2 5 5 0 1 2] 0.000016
fstat
num calls: 59 0% of syscalls
tot time: 0.000371 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000002
med call time: 0.000006
min/hist/max: 0.000004 [17 21 16 1 3 0 0 0 0 1] 0.000015
alarm
num calls: 87 1% of syscalls
tot time: 0.000425 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000001
med call time: 0.000005
min/hist/max: 0.000004 [23 0 0 52 0 0 11 0 0 1] 0.000007
mmap
num calls: 68 0% of syscalls
tot time: 0.000599 0% of syscall time, 0% of wall time
avg call time: 0.000009
+/-: 0.000002
med call time: 0.000009
min/hist/max: 0.000005 [ 1 5 11 14 17 8 7 2 1 2] 0.000014
rt_sigaction
num calls: 119 1% of syscalls
tot time: 0.000637 0% of syscall time, 0% of wall time
avg call time: 0.000005
+/-: 0.000001
med call time: 0.000005
min/hist/max: 0.000004 [ 9 65 0 43 0 0 1 0 0 1] 0.000010
getdents
num calls: 8 0% of syscalls
tot time: 0.002692 0% of syscall time, 0% of wall time
avg call time: 0.000337
+/-: 0.000560
med call time: 0.000010
min/hist/max: 0.000005 [6 0 0 0 0 0 0 0 0 2] 0.001319
stat
num calls: 1657 10% of syscalls
tot time: 0.016975 0% of syscall time, 0% of wall time
avg call time: 0.000010
+/-: 0.000008
med call time: 0.000010
min/hist/max: 0.000006 [1653 1 0 0 0 0 0 0 0 3] 0.000193
close
num calls: 4873 28% of syscalls
tot time: 0.029571 0% of syscall time, 0% of wall time
avg call time: 0.000006
+/-: 0.000003
med call time: 0.000006
min/hist/max: 0.000004 [4868 4 0 0 0 0 0 0 0 1] 0.000200
openat
num calls: 5128 30% of syscalls
tot time: 0.045333 0% of syscall time, 0% of wall time
avg call time: 0.000009
+/-: 0.000005
med call time: 0.000009
min/hist/max: 0.000005 [5123 3 0 0 0 0 0 1 0 1] 0.000251
read
num calls: 4900 29% of syscalls
tot time: 0.050589 0% of syscall time, 0% of wall time
avg call time: 0.000010
+/-: 0.000008
med call time: 0.000010
min/hist/max: 0.000004 [4893 1 0 0 0 4 1 0 0 1] 0.000307
nanosleep
num calls: 1 0% of syscalls
tot time: 0.150135 1% of syscall time, 1% of wall time
avg call time: 0.150135
+/-: 0.000000
med call time: 0.150135
min/hist/max: 0.150135 [0 0 0 0 1 0 0 0 0 0] 0.150135
pselect6
num calls: 2 0% of syscalls
tot time: 2.783874 10% of syscall time, 10% of wall time
avg call time: 1.391937
+/-: 1.391921
med call time: 1.391937
min/hist/max: 0.000016 [1 0 0 0 0 0 0 0 0 1] 2.783858
ppoll
num calls: 2 0% of syscalls
tot time: 25.012394 89% of syscall time, 88% of wall time
avg call time: 12.506197
+/-: 12.505751
med call time: 12.506197
min/hist/max: 0.000446 [1 0 0 0 0 0 0 0 0 1] 25.011948
매우 감사합니다.
===========
이 문제에 대한 업데이트.
문제는 ppoll로 인해 발생할 수 있습니다. 그러나 해결 방법을 모르겠습니다. 2일 후 문제가 사라졌습니다. 상위 프로그램을 다시 모니터링 strace해 보니 위의 출력에 비해 더 이상 시간이 많이 걸리지 않습니다 ppoll.
답변1
비슷한 문제가 있습니다. 이는 systemd-timesyncd이름이 아닌 사용자 ID로 식별되기 때문입니다 .
ps를 실행하면 다음과 같습니다. 재부팅을 해보았더니 일회성 문제였으나, 아이디를 사용자명으로 변환하려고 할 때 문제가 있었던 것 같습니다.
root 20366 779 0 21:05 ? 00:00:00 [autocleanStatus] <defunct>
root 20385 757 0 21:05 ? 00:00:00 sshd: git [priv]
<long hang>
62583 20396 1 2 21:06 ? 00:00:00 /lib/systemd/systemd-timesyncd
이는 문제에 도움이 되지 않을 수도 있지만 집중하는 데 도움이 될 수 있습니다.