Stealth Slow Query

この投稿は、PostgreSQL Advent Calendar 2017 の17日目で公開する記事です。
昨日は fujii_masaoさんの記事 でした。パーティションテーブルのオーバーヘッドが次の版では改善されるかもしれないとのこと、楽しみですね。

2016年にはpg_stats_reporter をしくじった話を書きました。今回もpg_stats絡みの実録です。実録といっても事象が複合して本筋と関係ない複雑さはばっさり切り捨てて、話を短くしてます。

巨大テーブルのパーティション分割

某サービスの最大テーブルが1億2千万行となって、将来の運用上のリスクや性能劣化リスクを見据えて、パーティション分割をしました。サービスの連携システムが夜間工事でとまるときサービス全体を停止することにして、その間に作業しました。当時25分割くらい。

いい機会なのでPostgreSQLもメジャーアップグレードしました。

スロークエリログの急増

パーティション分割工事後、スロークエリログが前日比で20倍も増えてしまいました。DBA真っ青です。

• log_min_duration_statement = 10で10msec以上をログ出力していました。
• スロークエリログの98%が１種類のSQL
• パーティション分割した最大テーブルを含むSQL

pg_stats_statement VIEW

問題のSQLについての統計情報をpg_stats_statement VIEWで観測しました。

• 夕方ピーク時で毎分1万calls=毎秒170calls
• total_time/calls だと1msec以下

callsもtotal_time/callsも工事前ととくに変化がないのです。

迷走

統計で1msec なのに 10msec-100msecのログが頻発　どういうこと？

• callの1%以下だけでスロー化？
• ユーザデータ依存？
• ログで100msec越えたパラメータでexplain analyzeしても実行2msec以下
• タイミング依存？
• PostgreSQL内部リソースの排他制御実装が変わった？
• changelog になし
• ソース見てもわからん

救いの神はtwitterから

ここで藤井さん、再登場です。下のtweetに救われました。

PostgreSQLでパーティション数が多いほどプラン生成時間が長くなる問題の確認 on @Qiita https://t.co/zheIkIihrr

— Fujii Masao (@fujii_masao) 2017年10月24日

スロー化の理由

• Planning time が 2msecから18msecに伸びていた
• 当SQLには CASE WHEN で実行されない副問い合わせが多数
• 全部で 11個 実行計画が80行
• PostgreSQLはパーティション分割数に比例してPlanning timeが伸びる
• fujii_masaoさんの検証によると100分割・単純SQLで＋1msecくらい
• 分割数は25だったが、分割オーバーヘッドがSQLの複雑さ＝11個の副問い合わせで掛け算されてる感じ

Stealth「見えない」理由

Justsystems 7日目担当のsugaiさんがソースからコメントを拾ってくれました。

pg_stat_statements.c

* We also don't track execution of PREPARE. If we did, we would get one
* hash table entry for the PREPARE (with hash calculated from the query
* string), and then a different one with the same query string (but hash
* calculated from the query tree) would be used to accumulate costs of
* ensuing EXECUTEs. This would be confusing, and inconsistent with other
* cases where planning time is not included at all.

雰囲気で意訳すると、SQL文字列のHash値がEXECUTEだけの場合とPREPAREを含む場合とで同じ値になるので、その処理時間全体を集計したのでは混乱・矛盾してしまう。そこでEXECUTEの時間だけを集計する方針のようです。

• Execution time は1-2msecで変化なかった
• pg_stats_statement VIEW では変化が見えない
• それをWeb表示するpg_stats_reporterでも当然見えない
• 事前性能検証しても見えてなかった

F-22と模擬空中戦をすると、相手が目の前を飛んでるのにレーダーが反応せずロックオンできないという怖い思いをするそうです。ふだん頼りにしているpg_stats_reporter, pg_stats_statementで見えないのに、スロークエリログに出てくるSQLは、Planning time >> Excution time という特殊ケースでした。

pg_stat_statementsの状況とスロークエリログの状況が乖離していて、なんじゃこりゃ、どうすりゃええんじゃとなってたけど、pg_stat_statementsにはPlanning timeが計上されてないとわかって落ち着いた。状況が解れば対策はできる。

— masuda kaz (@masudakz) 2017年10月26日

ちなみに、このトラブルシューティングはsugaiさんとのやりとりを含めて、Justsystems 6日目「トラブルシューティングを実況する」のようにSlackでやっています。

スロークエリ差し換え

• 仕様の一部見直し
• 副問い合わせなし LEFT JOIN 2つ、GROUP BY 1つのSQLに簡素化
• UXへの影響を最小にするためにJOIN数は削りきれず
• 呼び出し側のN+1問題を解消 call数を1桁削減
• 累計 180msec→9msecに短縮
• パーティション分割工事前と同等くらいのはず

このSQLは5年前から「スケールしない」と目をつけてたが、仕様も実装も複雑でUXに直結で、手を入れられず。N+1問題を解消して1/Nを残すような慈悲はない。駆逐してやる。1 call も残さず。仮実装の全開試験順調。配備すればあと??年は戦える。

— masuda kaz (@masudakz) 2017年11月1日

スロークエリ対策前後

DBのCPU userを1/3 cut。稼働コア数も削減

マカレルのグラフをニヤニヤしながら眺めて、平和をかみしめ、おでんとぽん酒。

— masuda kaz (@masudakz) 2017年11月16日

教訓

• pg_stat_statementsでは拾えないスロークエリもある
• 統計だけに頼るな　生ログも大事
• N+1問題は放置するな
• Databaseはシンプルに使え
• 10msecでもスロークエリ
• 頻度次第で。170call/sec x (CPU 10msec/call) = 1.7 core分を占有!

関連記事

よろしければこちらもご覧ください。実録記事の３連投でした。

• Monster Query Hunter
• Submarine Slow Query

PostgreSQLアンカンファレンス

前日2017-12-16のPostgreSQLアンカンファレンスでこの内容を発表してきました。Q&Aをまとめておきます。

Q:PostgreSQLアップグレードのバージョンは？
A:9.3から9.4でした。9.3までEXPLAIN ANALYZEの出力でPlanning timeが分離していなかったので、慣れていなくて、Planning timeに注目できなかったのも敗因でした。

Q:スロークエリログの足きりライン10msecはシビアじゃないですか。ちょっとしたIOの不調とかでもログが急増することがあるのでは？
A:会場のみなさんへの逆質問したいところ。みなさんどのくらいで使ってます？
O1: msec単位ではつかってないかな。1秒とか。
O2: TPSが1とかのシステムなんで、緩い

A:DAUがそれなりにあるWebサービスなので100msecとかはもう対処が必要になる。そうなる前の兆候をつかむためにはあまり緩くできない。今回のも11msecとかのが大量に出た。緩かったら、統計VIEWにも変化なし、ログにも出ずで、負荷だけあがるまずい状況に追い込まれていた。
ログストレージがSSDでスループットがあること、ちゃんとローテーションできていることが前提ですけど。