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を実行すると、次のようになります。再起動してみたところ、ワンタイム問題でしたが、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
これは問題には役に立たないかもしれませんが、集中するのに役立ちます。