よく知らないアプリケーションの性能と戦わないといけないときの防衛術（前編）

# よく知らないアプリケーションの性能と戦う、という状況

* **SNSにキャンペーン載せたらバズってサイトがずっと503なんです、なんとかなりませんか？**
* **バッチがいつもの時間に終わらないんですけど、急ぎ見てください！**

みたいな連絡を、そろそろ帰るかと思った21時とか明け方5時とかに電話が鳴って受けることって、そこそこあると思うんです。

私が設計したわけでもなく開発したわけでもなく、レビュー参加とかで辛うじて全体は分かるけど、いまからソース見る時間もないし、開発した方は性能面の対処が覚束ない。**突然性能面で火を噴いてなぜか自分が召喚されて2~3時間でどうにかしたい、という闇な状況**にどういうふうに対応していたっけ自分、というのを**経験則100%で書いてみよう**と思います。

**この前編は道具の紹介(OS編)、中編は道具の紹介(Java)、後編は道具の紹介(PostgreSQL)です。**
中編 → https://qiita.com/nfujita55a/items/555350e61b73db3a2b8c 

……あっ、たぶん変なところもあると思うので、ご指摘お待ちしております。

# 想定する環境

仕事柄、想定する環境はすごくレガシーです。クラウド(AWS EC2)でもオンプレでもいいのですが

```
[Webサーバー Linux Apache]
｜
[APサーバー Linux Java+Tomcat+WEBアプリケーション、Java+バッチプログラム]
｜
[DBサーバー Linux PostgrteSQL]
```

という構成を想定しています（サーバーは複数台でも1台でもいい）。えぇ、RDSとかLambdaとか、そういうサーバーレスなものは特にないから、OSから上、全部見れるよ、ってやつです。
*（最悪OSから下、ハードとかESXまで見ないといけない状況もあるけど、それはこの記事ではパス）*

# 「がんばってる、待ってる、土台がおかしい、誰かを待ってる、どれなのか？」それが問題だ

性能面で問題が生じているとき、どのサーバーも暇、というのはレアケースだ（そしてそうなら相当厄介だ）。だいたい、どれかのサーバーが悲鳴をあげてて問題が生じている。サーバー別には4つの状況がある、と言えるだろう。

1. CPUが計算を**がんばってる**
2. ディスクの応答を**待ってる**
3. (OSから見て)**土台がおかしい**。ハードとかESXとかストレージとか。
4. **誰かを待ってる**

まずは関連するサーバー群のうち問題を引き起こしているサーバーがどれで、それはどの状況にあたるのか特定したい、というわけで **vmstat** コマンドの出番である。

# 道具1.vmstat (重要)

というわけで、関連するサーバー群で、

```
$ vmstat 1
```

と叩く(rootに上がる必要もない)

こんなふうに出てくる。

```
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs  us sy id wa st
 0  1  98508 360384 135488 2872176    0    0 29952   148  758  610  7  1 75 17  0
 1  0  98508 379232 135496 2853328    0    0 24564     0  690  556  6  1 75 19  0
 0  1  98508 397460 135504 2835056    0    0 20344     0  716  572  5  1 75 20  0
 0  1  98508 393880 135512 2838664    0    0 36316     0  859  705  9  1 75 16  0
 0  1  98508 399776 135524 2832448    0    0 41720    20 1224 1034 10  2 74 15  0
 1  0  98508 363120 135524 2869356    0    0 36224   176  801  689  8  1 75 16  0
 1  0  98508 385936 135532 2846372    0    0 30804     0  789  643  7  1 75 17  0
 0  1  98508 355060 135532 2877156    0    0 30208     0  658  577  7  1 75 18  0
 0  1  98508 326788 135532 2905416    0    0 27648     0  607  532  6  1 75 19  0
 0  1  98508 376760 135544 2855436    0    0 25080    52  607  516  6  1 75 18  0
 0  1  98508 391400 135548 2840960    0    0 40896   140  919  800  9  1 75 15  0
 0  1  98508 362384 135548 2870172    0    0 28672     0  768  633  7  1 75 18  0
 1  0  98508 339940 135548 2893072    0    0 22352     0  531  470  5  0 75 20  0
 1  0  98508 360524 135684 2872208    0    0 34700     0  868  714  8  1 75 16  0
 1  0  98508 384664 135696 2847768    0    0 32332     8 1078  907  8  1 74 17  0
 0  1  98508 350920 135700 2881480    0    0 32896   200 1331 1071  8  1 74 17  0
 1  0  98508 362716 135708 2869696    0    0 30444     0  696  626  7  1 75 18  0
```

### us, sy, wa の把握

大雑把にはこうだ。**usやwaの合計値が80~100をウロウロしていたら、そのサーバーで問題が起きている**と思っていいだろう。50%以上でも十分要調査リストに入る。現代のCPUをフルに回すというのは大変な仕事のはずなのだ。

* us - プロセスがCPUが計算している(ユーザー時間)
* sy - LinuxのKernel（OS本体）がシステムコールを処理している(システム時間)
* wa - ディスクの読み書きをプロセスが待っている

もう一つ、特にバッチ処理の時にあるパターンなのだが(WEBアプリケーションでもたまに見る)、

* **us + wa が 100÷CPUコア数 に張り付いている(CPUコアが4なら100÷4の25)**
* (言い換えると) id が 100-(100÷CPUコア数に張り付いている) で推移している (CPUコアが4なら100-100÷4の75)

も**ほぼ確定に近い危険信号**だ。これはサーバーの中で並列処理になっていない1つのプロセスが、全力で処理している兆候だ(バッチの並列処理とか厄介だからね)。ZabbixとかCloudwatchでCPU監視してても警告されない。サーバーのお守りをしてる方も「*CPU使用率には問題ありませんよ*」と報告があがって来たりもする。実はヤバいやつだ。
ちょうど上の vmstat の出力結果がこれの該当例にあたる。(4コアのサーバーで id は 75、us+wa が 25)

**sy がもし5以上あるなら「何かおかしいぞ？」って考える**。現代のコンピューターにおいてシステムコールに時間を取られる、というのはまれだ。

* ファイルのオープンと1bitと書き込みとクローズを繰り返している(まとめて書けばいいのに)
* TCP/IPのソケット開いて閉じてを繰り返している(コネクションプーリングすればいいのに)
* 実はOSから下がダメになっていて（土台がおかしい）、どんな軽微な処理をするにも時間を要している

といった特異な状況が考えられる。そういうサーバーがあったらこれは怪しい。

「土台がおかしい」（言い換えると基盤がまずい）ってのはOSから上だけ見ているとき、基盤がまずいことに気づきにくいのだけど、調査していて後述する処理が負荷軽そうなのに時間がやたらにかかる＋いつものコマンドの応答に相当時間がかかる、とかそういうときに疑うのがいいかな、と思う。（基盤の担当に処理遅延してるから、念のため基盤の正常性を見てね、あとから詳細調査いくかもだけどごめんね、と急ぎ連絡しておくのも手だ）

### procs, io の把握

そして procs, io を把握する

procs の r は、ディスクを待たなくていい計算中なプロセス数の合計、b はディスクを待ってるプロセス数の合計だ。us, sy, wa と矛盾ないかを見ておこう。

io もこれから対応するにあたり見ておこう。bi はOS全体でディスクから読み込んでいるブロックデバイスの数、bo はOS全体でディスクに書き込んでいるブロックデバイスの数だ。

上の例だと、**「ある1つのプロセスが、ディスクを待ちながら多量に読み込み、何かをガチャガチャ計算し、何かチョコチョコ書いてるのかな？」**くらいまでつかめるとベターだ

### 念のため swap も

もし、**swap の si, so がたびたび4桁以上の値を出していたら、これも危険信号**だ。というか、運用上のサーバーが重たい処理中でswapin, swapoutが発生してたらまずい。さっさとリソース配分をAWSなりESXなりOSレイヤで調整するか、ミドルウェアとかの設定値で調整するか、舵を切る必要がある。

------
そんなふうにして怪しい、調べる「CPUがんばってる」あるいは「ディスク待ってる」サーバーを特定する。異常が見あたらないサーバーは「誰かを待ってる」といったん考えておこう。

# 道具2.free

次にざっとOSのメモリ使用状況を見ておこう

RHEL7(CentOS7)まではこんな表示で

```
$ free -m
             total       used       free     shared    buffers     cached
Mem:          3832       3324        508          0        146       1939
-/+ buffers/cache:       1237       2594
Swap:         4031        397       3634
```

RHEL8(CentOS8)はこんな表示だ

```
$ free -m
              total        used        free      shared  buff/cache   available
Mem:           3832        1237         508         140        2085        2454
Swap:          4031         397        3634
```

まず重要なのは、**RHEL7までの -/+ buffers/cache の free (上の例だと2594)、RHEL8(CentOS8)の Mem の available だ。これが実質的な空きメモリだ**。Linuxなら空きメモリをディスクバッファでめいっぱい使うので、ここが実質的な空きメモリである。
（*RHEL7までの free の上段にある 508 を見て、508MBしか空きメモリがない！と言ってくることが多かった*）

また

* プロセスが実際につかんでいるメモリの合計量(used)、上の例なら 1237
* OSがバッファーキャッシュに用意できているメモリ、上の例なら 146+1939 や 2454

も把握する。

昨日までちゃんと動いていたシステムが今日突然性能落ちた、といったここで扱うケースでは、なぜかOSにメモリ不足が問題になることは少ないのだけど（これは、Javaが一層噛んでいることが大きい）、実質的な空きメモリが少ない(512MBを切っている)ときは、メモリを増やすことも考えていいだろう。

そして、特に見ているサーバーが**DBサーバー**だったら(特に PostgreSQLでは)、**キャッシュにどれだけ回せるか**は性能を左右する。PostgreSQLなら

* shared_buffers で指定するPostgreSQLの共有メモリバッファ
* OSのバッファーキャッシュ

とキャッシュの概念が2つある。前者はOSの25%が推奨値なので、例えば8GB詰んでるOSがあったとき、used は 2048 くらいあるはずだ。そこまで達していなかったら、設定を間違っているか（デフォルトの128Mで放っておいて今日 :boom: したとか）、ボトルネックはほかの箇所でDBMSが問題ではない、となる。
また、OSのバッファーキャッシュが、WEBアプリケーションからもバッチからも処理中に高頻度で読み書きされるテーブル(のレコード範囲)に収まりそうか、も考える。
※どうやってよく知らないアプリケーションが問い合わせるSQLを取得するかは中編で説明、するはず

```
SELECT
    relname,
    reltuples as rows,
    (relpages * 8192) as bytes
FROM
    pg_class
WHERE
    relname = 'テーブル名'
```

みたいなので(postgresql table size で検索したらたくさん出てくるからお好きなものをどうぞ)、取得できたテーブルのサイズから

* 高頻度で読み書きされるテーブルのサイズ計 > freeコマンド の buff+cache サイズ
* free コマンドの実質的な空きメモリが少なく(128Mを切ってる、かな)、buff+cache が大きい
* vmstat 1 の bi (ディスク読み取り) がずっと多い(5桁ある状況が続く、IOが遅いサーバーなら4桁後半でも)

と**3つを満たす状況がDBMSなサーバーで見て取れたら、それはメモリ増設をして、PostgreSQLの共有メモリバッファやOSのバッファーキャッシュを増やす選択肢が出てくる。**

---

※（横道にそれるが）それくらいちゃんと設計して普段から運用で見ておこうよ、と私も思うのだけど、急に召喚されたときには

* 想定外の外部状況（アクセス量とかデータ量とか）
* 年月が経ち設計当時と今で状況が違う
* そもそも考えてなかった（別のことでいっぱいいっぱいだった）

とか何かしらあるのだ。**これらの不備は今、目の前で燃え盛っている火事をどうにか鎮火させてから取り組む方がいい**。鎮火させる前に「設計ちゃんとしないと、いま手を出せません」と正論で行くと「あてにならない人だなぁ」と不合理極まりない評価が降ってくることが多い。鎮火させた後「だから聞いてくださいな」ってしたほうがうまくいく。

# 道具3.netstat (ss)

次にTCP/IPの状況を見よう。netstat コマンド（ss コマンド）の出番だ。想定はこうだ。

|役割|受け付けるコネクション(サーバー側)|コネクション(クライアント側)|
|:-:|:-:|:-:|
|Webサーバー(Apache)|インターネット各所から443番に|APサーバーに8009番へ|
|APサーバー(Tomcat+バッチ処理)|Webサーバーから8009番に|DBサーバーに5432番へ|
|DBサーバー(PostgteSQL)|DBサーバーから5432番に|-|

いずれのサーバーでも

```
$ su - 
# netstat -tna
# ss -tna
(どちらでも慣れた方で、p をオプションにつけてプロセスを出してもいい)
```

と実行する。見るのは2つだ。

* **SYN_SENT(確立中-クライアント側), SYN_RECV(確立中-サーバー側) が一定数存在する状況が続いていたら、おそらくここがボトルネック**だ。「-tnap」とオプションをつけて、どのプロセスが問題か特定しよう。※Webサーバーはインターネット各所と通信だからESTABLISHED(確立済み)な通信の10~20%くらいあっていいかも
* 各サーバー間の通信数と各ミドルウェアの最大同時接続数との兼ね合い。ApacheならMaxClients、TomcatならmaxThreads、PostgreSQLならmax_connectionsと比較し、**各サーバー間の通信数が最大同時接続数に近づいていたら、ここがボトルネック**だ。

例えば、ある理由で自らがクライアントとなるバッチ処理で必要な通信が確立できず処理性能が低下してたサーバーはこんなふうになる。

```
# netstat -tna | grep XX
tcp        0      0 0.0.0.0:XX                   0.0.0.0:*               LISTEN
tcp        0      1 192.168.aa.bb:37325          相手先サーバー:XX       SYN_SENT
tcp        0   5966 192.168.aa.bb:34754          相手先サーバー:XX       ESTABLISHED
tcp        0    438 192.168.aa.bb:51938          相手先サーバー:XX       ESTABLISHED
tcp        0      1 192.168.aa.bb:38756          相手先サーバー:XX       SYN_SENT
tcp        0   5981 192.168.aa.bb:51292          相手先サーバー:XX       ESTABLISHED
tcp        0      1 192.168.aa.bb:47082          相手先サーバー:XX       SYN_SENT
tcp        0     10 192.168.aa.bb:60718          相手先サーバー:XX       ESTABLISHED
tcp        0      1 192.168.aa.bb:53764          相手先サーバー:XX       SYN_SENT
tcp        0      1 192.168.aa.bb:58367          相手先サーバー:XX       SYN_SENT
tcp        1     32 192.168.aa.bb:51641          相手先サーバー:XX       LAST_ACK
tcp        0      1 192.168.aa.bb:37870          相手先サーバー:XX       SYN_SENT
tcp        0      0 192.168.aa.bb:35569          相手先サーバー:XX       ESTABLISHED
tcp        0      1 192.168.aa.bb:43051          相手先サーバー:XX       SYN_SENT
tcp        0      1 192.168.aa.bb:44851          相手先サーバー:XX       SYN_SENT
tcp        0      1 192.168.aa.bb:37243          相手先サーバー:XX       SYN_SENT
tcp        0      1 192.168.aa.bb:46195          相手先サーバー:XX       SYN_SENT
tcp        0      0 192.168.aa.bb:40792          相手先サーバー:XX       TIME_WAIT
tcp        0      1 192.168.aa.bb:52571          相手先サーバー:XX       SYN_SENT
tcp        0      1 192.168.aa.bb:52123          相手先サーバー:XX       SYN_SENT
```

「なんでこんなに SYN_SENT してるの？これが問題っぽいな」という具合だ。

# 道具4.top

ようやく「どのプロセスか？」の話にたどり着いた。これの話はシンプルだ。

rootで # top d 1 と叩いて、下記のような表示がされる。上位にそのOSで処理負荷のかかっているプロセスが順に出てくる（これはある大量ファイルをgzipで圧縮かけている例）。
これを**目星をつけた要調査なサーバーはその中でどんなプロセスをぶん回しているか「vmstat、free、netstat(ss)」の結果を思い浮かべながら見る。**

```
top - 15:17:43 up 253 days, 21:00,  2 users,  load average: 0.95, 0.66, 0.35
Tasks: 166 total,   3 running, 163 sleeping,   0 stopped,   0 zombie
Cpu(s): 16.1%us,  2.0%sy,  0.0%ni, 52.0%id, 29.7%wa,  0.2%hi,  0.0%si,  0.0%st
Mem:   3924272k total,  3615104k used,   309168k free,   136212k buffers
Swap:  4128764k total,    98508k used,  4030256k free,  2921764k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
29719 root      20   0  4304  800  408 R 41.8  0.0   0:06.93 gzip
29770 root      20   0  4304  800  408 D 29.9  0.0   0:01.95 gzip
29816 root      20   0 15024 1360  992 R  1.0  0.0   0:00.01 top
    1 root      20   0 19360 1248 1076 S  0.0  0.0   6:00.10 init
    2 root      20   0     0    0    0 S  0.0  0.0   0:00.16 kthreadd
    3 root      RT   0     0    0    0 S  0.0  0.0   3:28.25 migration/0
    4 root      20   0     0    0    0 S  0.0  0.0   3:01.41 ksoftirqd/0
    5 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 stopper/0
    6 root      RT   0     0    0    0 S  0.0  0.0   4:14.15 watchdog/0
    7 root      RT   0     0    0    0 S  0.0  0.0   3:30.45 migration/1
```

**サーバーの役割の時点で、下記のように予測できるものなので、その通りかそれと異なる想定外のプロセスが忙しいか**を把握する。

|役割|忙しいと予測するプロセス|
|:-:|:-:|
|Webサーバー(Apache)|httpd|
|APサーバー(Tomcat+バッチ処理)|java|
|DBサーバー(PostgteSQL)|postgresql|