よく知らないアプリケーションの性能と戦う、という状況
- 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つの状況がある、と言えるだろう。
- CPUが計算をがんばってる
- ディスクの応答を待ってる
- (OSから見て)土台がおかしい。ハードとかESXとかストレージとか。
- 誰かを待ってる
まずは関連するサーバー群のうち問題を引き起こしているサーバーがどれで、それはどの状況にあたるのか特定したい、というわけで 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で放っておいて今日 
したとか）、ボトルネックはほかの箇所で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 |