Monster Query Hunter

この投稿は、JustSystems Advent Calendar 2017 の 10日目で公開する記事です。

世の中、どこにどんな怪物が潜んでいるかわかったものではありません。全長12KCharのモンスターSQLを高速化したときの記録を公開しましょう。

ハンターの帰還

1年留守にして某サービスに帰ってみると、夜間バッチが荒ぶっているんですよ。実ユーザのほとんどいない深夜から未明で終わるつもりだった新機能用のバッチ処理が24時間とか、ひどいときは72時間とか終わらない。月に1回の処理なので、未終了処理に新処理が重なって、という最悪事態にはなっていませんでしたが、処理中はDBServerの負荷も危険な水準まで上がってしまう。CPU全能力の50%以上の高水準が終日続いたのでは、サービス応答時間がユーザ体験にまで影響しかねない。
帰還したばかりの自分の工数ならしばらくリファクタリングに全振りできるでしょうから、この夜間バッチを見てみることにしました。

獲物探し

去年(2016年)にはこんな記事も書きました。

• pg_stats_reporter をしくじった話 PostgreSQL Advent Calendar 2016

バックエンドがPostgreSQLのサービスなので獲物探しにはpg_stats_reporterが最高に便利です。RDSではまだ使えないけれど。

分析の１ バッチ開始直後1時間のレンジを見る

24時間以上続いたバッチですが、最初のうちは接続ユーザがほとんどいないので、そこだけ切り取ればバッチ処理だけのふるまいが見えるはずです。

※実在サービスの話なのでテーブル名など伏字化しています。イメージしにくい名前ですみません。

• Disk Read中 i_q_results が99%
• u_k_details INSERT 137060行
• seq_tup_read で i_q_results 890回 x 8.5M行 = 7.5G行/hour
• seq_tup_read で u_r_courses 817回 x 5.5M行 = 4.5G行/hour
• seq_tup_read で q_master 890回 x 0.2M行 = 0.18G行/hour

Table行数

• i_q_results 28M行
• u_r_courses 6.1M行
• q_master 0.2M行

Long Transactions

• 最大100秒で、同型queryが8個

これでqueryはほぼ確定。やるべきことも、Giga行単位になる累計SeqScanをなんとかすること。ここまでは pg_stats_reporterのページ開いて、レンジ設定すれば、一目瞭然というところです。

分析の2 バッチ全体のpg_stats_reporter

バッチ処理全体のレンジで見ても開始直後のと傾向は同じでした。

• u_k_details INSERT 3,269,882
• seq_tup_read で i_q_results 21K回 x 8.6M行 = 183G行
• 問題のLong Transaction は全体で300回弱発生、max 152sec

SeqScan累計183Giga行!

「オ イ オ イ オ イ死 ぬ わ ア イ ツ」

バッチ処理の対象件数に比較して、Long Transactionsになったのが300と圧倒的に少数でした。テストデータを無作為に選んだのでは性能障害の本丸にたどり着けそうにないです。リリース前のテストで検出できなかったのはこれが理由かな。

まずは矢の1本も撃ってみる

pg_stats_reporter ではSQLが長すぎると全部は表示してくれませんが、見えている範囲でWITH句が3つほどあります。
この段階で遅かったらめっけものなので、WITH句をひとつずつ EXPLAIN ANALYZE

EXPLAIN ANALYZEについては、7日目のテーマになっています。
アプリケーションエンジニアのための実行計画

残念ながら、この範囲をちょっとみただけでは修正方針が立ちませんでした。

獲物の近くまで寄る

SQL全体が必要になったので、スロークエリログを見に行かねばなりません。
100秒以上かかったのがいるとわかっているので、

grep -A2 -E "期間: [0-9]{6}\.[0-9]" ～ でSQLと同時にそのパラメータも拾ってきます。

なにこれ、なにこれ、すごーい、全長が12KChar

長い長いSQL全体の構造だけ外形だけを把握しよう。

• pg_stats_reporter で見えていた3つ
• masterと名前のつくWITH句が5つ
  • k_c_master
  • k_r_master
  • k_i_master
  • k_e_master
  • k_m_master
• correct_p句で、対象ユーザの学習履歴からscore集計
• INSERTパートに3つ
  • うちひとつがu_k_details
• 診断パートに3つ
• 最終出力 INSERT INTO u_k_subjects

WITH句15個！　パラメータ数19個!　EXPLAIN ANALYZEしてみたら結果が300行!

こんな大物がプロダクトコードにいるのは見たことがなかった。

でかくてもコアが見えてるんだよ

masterの名がつくWITH句の結果なんて、更新頻度低そうな情報だろうから、マテリアライズド・ビューにすれば全体の見通しもよくなって、処理性能も向上しそうなものです。
リリース前なら踏み込みますが、リリース済みで処理結果も蓄積済みです。結果の互換性・結果の連続性について厳密な検証が必要になる大きな工事はできればやりたくないですね。

現状の実装から改善していく道をまずは探ってみます。
seq scan の統計をpg_stats_reporterで見ているので、大半を占めるi_q_resultsの参照状況 だけ に注目してみる。

correct_p句の1カ所だけ

FROM   i_c_results cr
JOIN i_q_results qr USING(course_result_id)

i_q_results.user_id にはindexがついていて、そちらも当然一致するはず。

JOIN i_q_results qr USING(user_id, course_result_id)

これで大幅に絞り込める。つまり、最終的には対象ユーザの結果だけが欲しいのに2つのテーブルをどかんとJOINしてからuser_idで絞り込む現状を、結合の時点でuser_idを使って中間結果を小さくしようぜ、ということ。

Seq scan の2番手 u_r_courses の参照箇所もすぐに見つかった

k_r_master句

JOIN u_r_courses rc USING(course_id)

ここも user_id の indexのみがある状態。条件にuser_idを追加する。というよりWHERE句から移す。

JOIN u_r_courses rc ON rc.user_id = $2 AND rc.course_id=r.course_id

これだけでいけそうだ。

げ、マルチコア個体だ

意気揚々と100秒パラメータで、改造SQLのEXPLAIN ANALYZEすると、

「あれ、大幅改善にはなったけど、こんなもんか？」

「あ、もうひとつコアが」

k_m_master句のUNIONの前半のu_r_courses 参照を見落としていました。
ここも上2箇所と同様に、user_id を早期評価してJOIN中間結果を減らす同じ方針で。

k_r_master句の修正対象箇所とそっくりなので、500行のSQLを40行程度のスクリーンで見ていたら、違うWITH句だと認識できずに見落としてしまったのでした。

長すぎるコードは本当によくない。

大団円

• 3ヵ所のJOIN条件に user_id を追加するだけ
  • コードレビューだけで等価保証できて運用投入できた
• 60時間程度かかっていた処理が、2時間30分で終了

その他の改良案

• master句をマテリアライズド・ビューにする
• LEFT JOIN になっているところを要件確認しつつJOINにできれば、結合則・交換則が使えて実行プランナがよりよいプランにしてくれるかも
• 対象ユーザ1人につきSQL1回実行する巨大なN+1問題になってるのも、対象ユーザ全部を一気にやるRDBらしい処理に全面改訂

という具合にアイデアはありますが、00:00に開始して05:00までに終われば、当面の性能要件は満たしているのです。
「早すぎる最適化はしないでおこうな」

140字まとめ

「パークの危機なのだ。野生開放。巨大セルリアンを打ち倒せ」
DBA語：運用DB負荷が平常の2倍超になるバッチが流れた。1年ぶりに`pg_stats_reporter`開いて、全長12Kchars With句12個のSQLから、累計270G行分のSeq Scanを除いて無害化せよ。

— masuda kaz (@masudakz) 2017年9月13日

DBAは外部化できる

上記のエンジニアリングにアプリケーション知識をほとんど使っていないことにお気づきでしょうか。実際、アプリケーションコードは1行も読んでいませんし、「新機能」の要件・概要の文書すら読んでないうちに作業終了しています。ログから拾ったSQLだけ見てやりました。またひとつ徳を積んで夢に近づいてしまった。

「蟲師」のような流れ者DBA。全国のRDBユーザを周期巡回
「すろーくえりはでてないかね」
「狂った統計情報があらぶってないかね」
「かすたむえすきゅーえるをせんじてあげよう」
「一本いんでっくすを追加しておいたのですぐによくなる」
というのを1ユーザあたり一泊二日。

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

隗より始めよ

RDB技術の汎用部分は潰しがききますから、外から入ってきても、いきなり事業貢献のチャンスがあります。毎度どったんばったん大騒ぎしてます。
こちらもご参照ください。

こういったデータベースまわりの話が好きな人にもっと来てほしいですね。　：アプリケーションエンジニアのための実行計画 on @Qiita https://t.co/CZpRTqLWYo

— 三木雅之 (@miki_cdo) 2017年12月7日

うちのTさんは50歳代でコードを書いて技術成果を出し続け年収1000万超。
マネージャーなど管理系にいかなくてもプロ技術者としてのキャリアパスがあることを共有して増やしたい。

— 三木雅之 (@miki_cdo) 2016年9月20日

ここ読んだよ、を証す合い言葉は「ポスグレ、チョットデキル。4桁万円ホシイ」で。

※ お断り）記事は全て個人の見解です。会社・組織を代表するものではありません。