命令“top”和“ps”需要很长时间才能显示结果

命令“top”和“ps”需要很长时间才能显示结果

最近,我发现当我在服务器上运行类似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

这可能对你的问题没有帮助,但可能有助于集中注意力。

相关内容