3

Recently, I find when I run commands like top or ps -aux on a server, it is very slow to show the result (STDOUT). I have checked the usage of disk space, memory, and CPU, all of them are OK.

After read some online materials, I also run the command strace -o strace_report.txt top. However, I didn't understand the report and cannot find any problem in the report. The elapse time of top program is 24 seconds in the problem server, but in another server, it only takes 2 seconds.

The running time of top command on a problemed server.

real    0m23.988s
user    0m0.023s
sys     0m0.025s

The running time of top command on a normal server.

real    0m2.462s
user    0m0.017s
sys     0m0.011s

It is weird that not all commands are running slowly. I also tested commands like ls and get the output immediately.

Could anyone teach me how to figure out where the problem is?

Based on @berndbausch 's suggestion, I summarize the strace output via stracestats.

I am not familiar with the output meaning of strace. Could anybody help me to confirm that if the problem comes from ppoll ?

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

Many thanks.

============

An update on this issue.

The problem may be caused by ppoll. However, I don't know how to fix it. 2 days later, the problem disappeared. I use strace to monitor the top program again, and compared with the output above, ppoll doesn't take a large of time anymore.

3
  • How did you measure the run time of top? By default it runs forever until you stop it. In any case, I would have used strace. Run the same test on the slow system and another system and create a histogram of system calls. Or compare system call timings. You should see a difference. Mar 17, 2021 at 14:01
  • @berndbausch I measure the running time using time top, when I see the command shows output, I stop it immediately, I know the measure is inaccurate, but it shows what I want to explain, I take half-minute to see the command output. BTW, my internet doesn't have any problem. Thank you for your suggestion on comparing the strace result of two servers. Do you know if the version of the servers (16.04 and 18.04) will affect the compare results?
    – Lijia Yu
    Mar 17, 2021 at 14:18
  • We can't know if there has been a dramatic update of top or ps between 16 and 18. However, the main problem is probably the fact that the process table is not identical between the two systems. This may make comparisons difficult. My hope is that the huge time difference dwarves all other differences. Mar 17, 2021 at 15:02

1 Answer 1

1

I had a similar issue. It was caused by systemd-timesyncd being identified by a userid rather than a name.

When running ps it would look like the below. I tried rebooting and it was a one off issue, but there was clearly an issue trying to convert the id to a username.

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

That probably doesn't help your issue, but might help focus down.

2
  • Thanks David! That issue never happened again, because I used another server instead of it.
    – Lijia Yu
    May 31, 2022 at 1:08
  • lol I'm having the exact same issue, also 62583... Jan 26, 2023 at 16:40

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .