最近,我发现当我在服务器上运行类似top
或 之类的命令时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
再次监控top程序,与上面的输出相比, ppoll
不再花费大量时间。
答案1
我有类似的问题。这是由于systemd-timesyncd
通过用户 ID 而不是名称来识别造成的。
运行 ps 时,它看起来像下面这样。我尝试重新启动,这是一个一次性问题,但在尝试将 ID 转换为用户名时显然存在问题。
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
这可能对你的问题没有帮助,但可能有助于集中注意力。