ボトルネックを調べる方法

最新版は以下に記載しました。
https://hana-shin.hatenablog.com/entry/2024/01/29/221206

#1 環境

```
[root@master test]# cat /etc/redhat-release
CentOS Linux release 7.2.1511 (Core)

```


#2 事前準備
stressコマンドをインストールする。
stressコマンドのインストール、使い方は、[ここ](http://qiita.com/hana_shin/items/b1d8cd559d1a326f4d42)を参照ください。



#3 CPU使用率(%cpu)の高い順にプロセスを表示する
psコマンドを使って、CPU使用率(%CPU)の高い順にプロセスを表示する。

```
stressコマンド(CPU負荷をかける)を起動する。
[root@master ~]# stress -c 1 -q &
[1] 1994

ジョブを確認する。1つ起動していることがわかる。
[root@master ~]# jobs
[1]+  実行中               stress -c 1 -q &

CPU使用率(上位5個)を確認する。stressのCPU使用率が90.5%であることがわかる。
[root@master ~]# ps ax --sort=-%cpu -o command,pid,pid,%cpu|head -n 6
COMMAND                        PID    PID   %CPU
stress -c 1 -q                1995   1995 ★90.5
/usr/bin/docker-current dae   1025   1025    7.5
/usr/bin/kubelet --logtostd   1360   1360    7.3
/usr/bin/kube-proxy --logto   1027   1027    5.7
[rcu_sched]                    137    137    5.3
[root@master ~]#

もう1つ、stressコマンド(CPU負荷をかける)を起動する。
[root@master ~]# stress -c 1 -q &
[2] 2020

ジョブを確認する。2つ起動していることがわかる。
[root@master ~]# jobs
[1]-  実行中               stress -c 1 -q &
[2]+  実行中               stress -c 1 -q &

CPU使用率(上位5個)を確認する。stressのCPU使用率が104%,98.8%であることがわかる。
[root@master ~]# ps ax --sort=-%cpu -o command,pid,pid,%cpu|head -n 6
COMMAND                        PID    PID   %CPU
stress -c 1 -q                2021   2021  ★104
stress -c 1 -q                1995   1995 ★98.8
/usr/bin/docker-current dae   1025   1025    7.3
/usr/bin/kubelet --logtostd   1360   1360    7.2
/usr/bin/kube-proxy --logto   1027   1027    5.5
[root@master ~]#

ジョブを終了する。
[root@master ~]# kill %1
[root@master ~]# kill %2
[1]-  Terminated              stress -c 1 -q
[2]+  Terminated              stress -c 1 -q

ジョブを確認する。2つとも終了したことがわかる。
[root@master ~]# jobs
[root@master ~]#

```


#4 メモリ使用量(RSS)の多い順にプロセスを表示する
psコマンドを使って、メモリ使用量(RSS)の多い順にプロセスを表示する。

```
メモリ使用量(RSS)トップ5のプロセスを確認する(初期状態の確認)。
[root@master ~]# ps ax --sort=-rss -o command,pid,ppid,vsz,rss|head -n 6
COMMAND                        PID   PPID    VSZ   RSS
/usr/bin/python -Es /usr/sb    519      1 331584 32096
/usr/lib/systemd/systemd-jo    348      1  69276 19332
/usr/lib/polkit-1/polkitd -    652      1 528276 12668
/usr/sbin/rsyslogd -n         1011      1 252140 12356
/usr/sbin/NetworkManager --    570      1 438032  8252

stressコマンドを実行する。vm-hangオプションを付けると、256M(デフォルト値)の実メモリを確保したままの状態になる。
[root@master ~]# stress -m 1 --vm-hang 0 -q &
[1] 16733
[root@master ~]# jobs
[1]+  実行中               stress -m 1 --vm-hang 0 -q &

メモリ使用量(RSS)トップ5のプロセスを確認する。stressが256Mメモリを消費していることがわかる(★印）。
[root@master ~]# ps ax --sort=-rss -o command,pid,ppid,vsz,rss|head -n 6
COMMAND                        PID   PPID    VSZ     RSS
stress -m 1 --vm-hang 0 -q   16734  16733 269400 ★262284
/usr/bin/python -Es /usr/sb    519      1 331584   32096
/usr/lib/systemd/systemd-jo    348      1  69276   19332
/usr/lib/polkit-1/polkitd -    652      1 528276   12668
/usr/sbin/rsyslogd -n         1011      1 252140   12356

もう1つ、stressコマンドを実行する（この時点で2つ起動)。
[root@master ~]# stress -m 1 --vm-hang 0 -q &
[2] 16737

ジョブを確認する。stressコマンドが2つ起動していることがわかる。
[root@master ~]# jobs
[1]-  実行中               stress -m 1 --vm-hang 0 -q &
[2]+  実行中               stress -m 1 --vm-hang 0 -q &

メモリ使用量(RSS)トップ5のプロセスを確認する。stressコマンドが各々256Mのメモリを消費していることがわかる(★印)。
[root@master ~]# ps ax --sort=-rss -o command,pid,ppid,vsz,rss|head -n 6
COMMAND                        PID   PPID    VSZ     RSS
stress -m 1 --vm-hang 0 -q   16734  16733 269400 ★262284
stress -m 1 --vm-hang 0 -q   16738  16737 269400 ★262284
/usr/bin/python -Es /usr/sb    519      1 331584   32072
/usr/lib/systemd/systemd-jo    348      1  69276   19332
/usr/lib/polkit-1/polkitd -    652      1 528276   12668

あと始末をする(stressコマンドを終了する）。
[root@master ~]# jobs
[1]-  実行中               stress -m 1 --vm-hang 0 -q &
[2]+  実行中               stress -m 1 --vm-hang 0 -q &

ジョブを終了する。
[root@master ~]# kill %1
[root@master ~]# kill %2
[1]-  Terminated              stress -m 1 --vm-hang 0 -q
[2]+  Terminated              stress -m 1 --vm-hang 0 -q

ジョブを確認する。2つとも終了したことがわかる。
[root@master ~]# jobs
[root@master ~]#

```




#5 ディスクアクセスの割合が高いプロセスを調べる方法
##5.1 事前準備(iotopのインストール)

```
[root@master test]# yum install iotop
[root@master test]# iotop --version
iotop 0.6

```

##5.2 バッチモードを使った調べ方

パラメータの意味

- t => 時刻を表示する。
- b => バッチモード.実行結果をファイルにリダイレクトする時に使う。
- o => I/Oを実行しているプロセスだけを表示する。
- d => iotopの実行間隔(秒)を指定する。


```
iotopの実行結果をファイルにリダイレクトする。1秒間隔で情報を採取する。
[root@master test]# iotop -t -b -o -d 1 > iotop.txt
-以下、略-

stressコマンド(I/O負荷)を実行する。
[root@master test]# stress -d 1 -q &
[1] 9682

採取したファイルからstressコマンドだけ絞り込む。
stressプロセスのディスクアクセス率が高いことがわかる(★印)。
[root@master test]# cat iotop.txt |grep -w stress
22:04:58   9683 be/4 root        0.00 B/s   65.23 M/s  0.00 % ★89.09 % stress -d 1 -q
22:04:59   9683 be/4 root        0.00 B/s   60.29 M/s  0.00 % ★80.59 % stress -d 1 -q
22:05:00   9683 be/4 root        0.00 B/s   66.61 M/s  0.00 % ★83.27 % stress -d 1 -q
22:05:02   9683 be/4 root        0.00 B/s   50.87 M/s  0.00 % ★51.99 % stress -d 1 -q
22:05:03   9683 be/4 root        0.00 B/s   56.02 M/s  0.00 % ★13.90 % stress -d 1 -q
22:05:04   9683 be/4 root        0.00 B/s   82.53 M/s  0.00 % ★73.77 % stress -d 1 -q
22:05:05   9683 be/4 root        0.00 B/s   75.23 M/s  0.00 % ★45.38 % stress -d 1 -q
22:05:07   9683 be/4 root        0.00 B/s   56.95 M/s  0.00 % ★24.16 % stress -d 1 -q
[root@master test]#

```


##5.3 interactiveモードを使った調べ方

```
stressコマンドを実行する。
[root@master ~]# stress -d 1 -q &
[1] 16860

ジョブを確認する。stressが1つ起動していることが確認できる。
[root@master ~]# jobs
[1]+  実行中               stress -d 1 -q &

iotopを実行する。
[root@master ~]# iotop
```
![iotop1.png](https://qiita-image-store.s3.amazonaws.com/0/146813/d8876996-d3e9-d0ef-808d-248ace805a37.png)


```
stressコマンドを実行する。(この時点でstressプロセスが2つ動作していることになる）
[root@master ~]# stress -d 1 -q &
[2] 16865

ジョブを確認する。stressが2つ起動していることが確認できる。
[root@master ~]# jobs
[1]-  実行中               stress -d 1 -q &
[2]+  実行中               stress -d 1 -q &

iotopを実行する。
[root@master ~]# iotop

```
![iotop2.png](https://qiita-image-store.s3.amazonaws.com/0/146813/5f86146e-3522-7f95-55de-f026afc7e1c9.png)




#6 ディスク使用量の多いディレクトリの求め方

##6.1 duコマンドが出力する数値の意味
ファイルが使用するディスク使用量を4K単位で出力する。

```
サイズが10バイトのファイルを作成する。
[root@master dd]# head -c 10 /dev/urandom > test.txt
[root@master dd]# ls -l test.txt
-rw-r--r-- 1 root root 10  3月  1 22:26 test.txt

ディスク使用量を確認する。4k使用していることがわかる。
[root@master dd]# du -h .|sort -rhk1,1
4.0K    .

サイズが4096バイトのファイルを作成する。ディスク使用量は4K
[root@master dd]# head -c 4096 /dev/urandom > test.txt
[root@master dd]# ls -l test.txt
-rw-r--r-- 1 root root 4096  3月  1 22:30 test.txt
[root@master dd]# du -h .|sort -rhk1,1
4.0K    .

サイズが4097バイトのファイルを作成する。ディスク使用量が8Kになったことがわかる。
[root@master dd]# head -c 4097 /dev/urandom > test.txt
[root@master dd]# ls -l test.txt
-rw-r--r-- 1 root root 4097  3月  1 22:30 test.txt
[root@master dd]# du -h .|sort -rhk1,1
8.0K    .

```


##6.2 ディスク使用量の多いディレクトリをしらべる
```
初期状態を確認する。
[root@master dd]# ls
[root@master dd]# du -h .|sort -rhk1,1
0       .

ファイルを作成する。
[root@master dd]# dd if=/dev/zero of=test.txt bs=1024 count=100000
-中略-

ファイルサイズを確認する。
[root@master dd]# ls -l
合計 100000
-rw-r--r-- 1 root root 102400000  3月  1 22:16 test.txt

ディスク使用量を確認する。
[root@master dd]# du -h .|sort -rhk1,1
98M     .
[root@master dd]#

ファイルを作成する。
[root@master dd]# mkdir test1
[root@master dd]# dd if=/dev/zero of=./test1/test.txt bs=1024 count=100000
-中略-

ディスク使用量を確認する。
[root@master dd]# du -h .|sort -rhk1,1
196M    .
98M     ./test1

```

#7 CPU steal
[Understanding CPU Steal Time - when should you be worried?](http://blog.scoutapp.com/articles/2013/07/25/understanding-cpu-steal-time-when-should-you-be-worried)
[Understanding CPU Steal – An Experiment](http://www.stackdriver.com/understanding-cpu-steal-experiment/)



#8 カーネルの送受信処理にかかる時間の求め方
##8.1 採取データ
ping(GW宛)を実行して、straceとtcpdumpを同時に実行する。

```
--------------------
1. strace実行結果
--------------------
straceを実行する。<>内の時間は、システムコールの実行完了にかかった時間(-Tオプション)を表す。
したがって、sendmsgからの復帰時刻は、20:37:53.962806 + 0.000431 = 53.963237 となる。recvmsgも同様である。
[root@master tcpdump]# strace -ttT -f -e trace=sendmsg,recvmsg  ping -c 1 192.168.0.1 > /dev/null
20:37:53.962806 sendmsg(3, -中略- = 64 <0.000431>
20:37:53.963762 recvmsg(3, -中略- = 84 <0.004102>

--------------------
2. tcpdump実行結果
--------------------
tcpdumpは、カーネルからドライバにIPパケットを渡すときにキャプチャされるものです。
したがって、下記左端の時刻は、T2,T3の時刻を表す。
[root@master tcpdump]# tcpdump -i eth0 icmp
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
20:37:53.963278 IP master > 192.168.0.1: ICMP echo request, id 1865, seq 1, length 64
20:37:53.967752 IP 192.168.0.1 > master: ICMP echo reply, id 1865, seq 1, length 64

```


##8.2 環境

```
   +------- master ------+
   |                     |
   |              ping   |
   |                |    |
   |                |    |
   |   T4          T1    | T1,T4の時刻はstraceで求める。
   |  +----------------+ | ともにシステムコールから復帰する時刻です。
   |  |     kernel     | |　　T1=20:37:53.962806 + 0.000431 = 20:37:53.963237
   |  +----------------+ |    T4=20:37:53.963762 + 0.004102 = 20:37:53.967864
   |    |           |    |
   |    |           |    |
   |   T3          T2    | T2,T3の時刻はtcpdumpより求める。
   |    |           |    |    T2=20:37:53.963278
   |    |           |    |    T3=20:37:53.967752
   |  +----------------+ |
   |  | Network driver | | カーネルの送信処理に費やした時間(T2-T1) = 53.963278 - 53.963237
   |  +----------------+ |                                      = 0.000041(41μ秒)
   |    |           |    |
   |    |           |    | カーネルの受信処理に費やした時間(T4-T3) = 53.967864 - 53.967752
   +----|--- eth0 --|----+                                      = 0.000112(112μ秒)
        |           |
        |           |
        <---　GW <--+

```



#9 ネットワーク遅延をおこす疑似環境構築

##9.1 環境
カーネルとドライバの間にqdiscと呼ばれるキューがあります。
カーネルがドライバにIPパケットを渡すととき、このqdiscを経由します。
qdiscでは、IPパケットの送信順序の並べ替えや、廃棄、シェーピング等の制御ができます。

```

   +------- master ------+               +------- node1 -------+
   |                     |               |                     |
   |              ping   |               |                     |
   |                |    |               |                     |
   |  +----------------+ |               |  +----------------+ |
   |  |     kernel     | |               |  |     kernel     | |
   |  +----------------+ |               |  +----------------+ |
   |    A           |    |               |     A         |     | ★遅延設定ポイント
   |    |           |    |               |     |        ★     |  (tcコマンドを実行して遅延を設定する）
   |    |           |    |               |     |      (qdisc)  |
   |    |           |    |               |     |         |     |
   |  +----------------+ |               |  +----------------+ |
   |  | Network driver | |               |  | Network driver | |
   |  +----------------+ |               |  +----------------+ |
   |    |           |    |               |     |         |     |
   |    |           |    |               |     |         |     |
   +----|--- eth0 --|----+               +-----|-- eth0 -|-----+
        |     | .10 |                          |     |.20|
        |     |     +------ ICMP req ----------+     |   |
        |     |                                      |   |
        |     +============ 192.168.0.0/24 ==========+   |
        |                                                |
        +------------------ ICMP resp -------------------+


```


##9.2 遅延の設定、状態表示、削除

```
1000ミリ秒の遅延を設定する。
[root@node1 ~]# tc qdisc add dev eth0 root netem delay 1000ms

設定を確認する。
[root@node1 ~]# tc qdisc show dev eth0
qdisc netem 8002: root refcnt 2 limit 1000 delay 1.0s

設定を削除する。
[root@node1 ~]# tc qdisc del dev eth0 root

設定を確認する。
[root@node1 ~]# tc qdisc show dev eth0
qdisc pfifo_fast 0: root refcnt 2 bands 3 priomap  1 2 2 2 1 2 0 0 1 1 1 1 1 1 1 1

```


##9.3 効果の確認

```
-----------------------------
1. 遅延を設定しない場合
-----------------------------
pingを実行する。実行完了に約18ミリ秒(★印)かかっていることがわかる。
[root@master ~]# ping -c 1 192.168.0.20
PING 192.168.0.20 (192.168.0.20) 56(84) bytes of data.
64 bytes from 192.168.0.20: icmp_seq=1 ttl=64 time=17.8 ms

--- 192.168.0.20 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = ★17.846/17.846/17.846/0.000 ms

----------------------------------
2. 遅延(1000ミリ秒)を設定した場合
----------------------------------
1000ミリの遅延を設定する。
[root@node1 ~]# tc qdisc add dev eth0 root netem delay 1000ms

pingを実行する。実行完了に約1118ミリ秒(★印)かかっていることがわかる。
[root@master ~]# ping -c 1 192.168.0.20
PING 192.168.0.20 (192.168.0.20) 56(84) bytes of data.
64 bytes from 192.168.0.20: icmp_seq=1 ttl=64 time=1118 ms

--- 192.168.0.20 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = ★1118.091/1118.091/1118.091/0.000 ms

設定を削除する。
[root@node1 ~]# tc qdisc del dev eth0 root


----------------------------------
3. 遅延(2000ミリ秒)を設定した場合
----------------------------------
2000ミリの遅延を設定する。
[root@node1 ~]# tc qdisc add dev eth0 root netem delay 2000ms

pingを実行する。実行完了に約2011ミリ秒(★印)かかっていることがわかる。
[root@master ~]# ping -c 1 192.168.0.20
PING 192.168.0.20 (192.168.0.20) 56(84) bytes of data.
64 bytes from 192.168.0.20: icmp_seq=1 ttl=64 time=2011 ms

--- 192.168.0.20 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = ★2011.925/2011.925/2011.925/0.000 ms

```


#X 参考情報
[lookbusy -- a synthetic load generator](https://www.devin.com/lookbusy/)
[iotopでLinuxのプロセス毎のディスクI/Oを監視する](https://www.agilegroup.co.jp/technote/iotop.html)
perfコマンド