testing some thing

■お問い合わせプロダクトバージョン
PostgreSQL 9.2.18

■問い合わせ

DBのCPU使用率が3％から60％まで急激に上がり、その後元に戻るといった事象が発生しました。
原因の調査をお願いします。

■回答

ご質問いただいているCPU使用率の増加は、一時的なDBの業務量の増加に伴うものであった可能性が考えられます。

ご提供いただいたログ等を確認したところ、CPU使用率が上昇していた期間において、DBに対して定常時の数倍の接続数があったことが確認できました。

該当の時間帯で業務量に変化がなかったかご確認ください。

また、事象が発生した時間帯で10分程度開いたままのトランザクションをもつプロセス（PID：36984）が見つかりました。このトランザクション内でレコードに変更が行われていた場合、他のトランザクションからの可視性判断が発生するため、各バックエンドプロセスのCPU使用率が上昇する可能性があります。COMMIT/ROLLBACKの漏れが無いか業務APを確認することをお勧めします。

※CPUの上昇に関しては、クエリの実行計画の変動によって発生することもありますが、今回の事象についてはクエリの実行計画の変動による影響の可能性は低いと考えます。
クエリの処理時間が log_min_duration_statement の設定値を超えたことを示すメッセージが出力されていましたが、これらのクエリにはヒント句が使用されているため、定常時よりこれらのクエリが遅延している場合はCPUリソースの枯渇によって遅延が発生した可能性が考えられます。

ご提供いただいた情報から以下の状況を確認できました。

・バックエンド数（DBへの接続数）増加

DBサーバのpsログからバックエンドプロセスを確認したところ、事象発生前はトータル99接続でしたが、CPU使用率が高騰していた時間帯では、233プロセスに増加していました。

事象発生時間帯の接続数の遷移は以下のとおりです。

time,total,front#1,front#2,front#2,back#1,other
2017-06-02 13:27:01, 99, 45, 36, 4, 4, 10
2017-06-02 13:28:01, 99, 44, 36, 4, 3, 12
2017-06-02 13:29:01, 100, 45, 36, 4, 3, 12
2017-06-02 13:30:01, 104, 47, 36, 6, 5, 10
2017-06-02 13:31:01, 233, 159, 53, 6, 5, 10
2017-06-02 13:32:01, 233, 159, 53, 6, 5, 10
2017-06-02 13:33:01, 233, 159, 53, 6, 5, 10
2017-06-02 13:34:01, 117, 52, 45, 6, 4, 10
2017-06-02 13:35:01, 112, 49, 43, 6, 4, 10

・実行キューの待機数の増加

DBサーバのvmstat情報から該当の時間帯でprocsのrが増加（実行キューに入ったプロセスが処理待ち）していることが確認できました。
バックエンド数の増加と合わせて考えると、業務量が増えたため、その分がrの値として見えたものと推察されます。

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 0 125488 2328164 17932 60258668 10 0 394 1894 8803 6210 4 0 96 0 0
2 0 125472 2327928 18008 60259524 14 0 166 970 11277 6904 5 0 94 0 0
43 0 125420 2009444 18268 60271748 33 0 402 1944 34432 6754 49 2 50 0 0
49 0 125276 1709612 18296 60245904 38 0 101 662 59025 7406 93 3 4 0 0
50 0 125256 1592620 18096 60240268 11 0 290 5232 52279 6231 95 2 3 0 0
50 0 125256 1480876 18260 60240464 0 0 58 114 50265 5353 95 2 3 0 0
・・・
47 0 125016 333476 15328 58343828 1 0 303 5214 55553 12478 80 3 17 0 0
30 0 124992 276560 15412 58344400 14 0 141 566 52946 13345 75 2 24 0 0
12 0 124968 2325648 15356 58345436 20 0 500 1819 46659 20857 35 3 63 0 0
9 0 124912 3953020 15316 58346240 26 0 163 750 27622 15350 15 1 84 0 0
12 0 124900 4168656 15492 58347384 9 0 543 1734 19416 11323 9 1 90 0 0

・CPU使用率の高騰

DBサーバのsarログを確認したところ、ご質問いただいている時間帯でCPU使用率が高騰していることを確認しました。ただし、iowaitが低いことやiostatのutilが低いことから、主に参照処理が行われており、また、その処理はメモリ内で行われていたことがわかります。

CPU %user %nice %system %iowait %steal %idle
13:30:16 all 6.10 0.00 0.42 0.04 0.00 93.44
13:30:21 all 3.69 0.00 0.21 0.03 0.00 96.07
13:30:26 all 5.19 0.00 0.39 0.01 0.00 94.41
13:30:31 all 45.68 0.00 1.70 0.04 0.00 52.59
13:30:36 all 92.94 0.00 3.35 0.01 0.00 3.70
13:30:41 all 94.54 0.00 2.09 0.01 0.00 3.35
13:30:46 all 94.97 0.00 1.61 0.00 0.00 3.42
・・・
13:33:21 all 94.83 0.00 1.17 0.01 0.00 3.99
13:33:26 all 94.44 0.00 1.12 0.01 0.00 4.43
13:33:31 all 86.69 0.00 2.03 0.03 0.00 11.25
13:33:36 all 75.56 0.00 4.47 0.03 0.00 19.94
13:33:41 all 79.96 0.00 2.69 0.03 0.00 17.32
13:33:46 all 75.38 0.00 1.88 0.02 0.00 22.73
13:33:51 all 36.30 0.00 2.79 0.03 0.00 60.89
13:33:56 all 15.15 0.00 1.29 0.01 0.00 83.55
13:34:01 all 9.61 0.00 0.63 0.02 0.00 89.75
13:34:06 all 7.33 0.00 0.39 0.03 0.00 92.25

[2017年6月9日時点]