Monster Query Hunter

この投稿は、[JustSystems Advent Calendar 2017](https://qiita.com/advent-calendar/2017/justsystems) の 10日目で公開する記事です。

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

# ハンターの帰還

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

# 獲物探し

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

- [pg_stats_reporter をしくじった話 PostgreSQL Advent Calendar 2016](https://qiita.com/masudakz/items/8e5643d5e3fcbf245fb5)

バックエンドが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日目のテーマになっています。
[アプリケーションエンジニアのための実行計画](https://qiita.com/sugai/items/6905f66eaebbac05f3a2)

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


# 獲物の近くまで寄る

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カ所だけ

```sql
FROM   i_c_results cr
JOIN i_q_results qr USING(course_result_id)
```

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

```sql
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`句

```sql
JOIN u_r_courses rc USING(course_id)
```

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

```sql
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字まとめ

<blockquote class="twitter-tweet" data-lang="ja"><p lang="ja" dir="ltr">「パークの危機なのだ。野生開放。巨大セルリアンを打ち倒せ」<br>DBA語：運用DB負荷が平常の2倍超になるバッチが流れた。1年ぶりに`pg_stats_reporter`開いて、全長12Kchars With句12個のSQLから、累計270G行分のSeq Scanを除いて無害化せよ。</p>&mdash; masuda kaz (@masudakz) <a href="https://twitter.com/masudakz/status/907954011948572672?ref_src=twsrc%5Etfw">2017年9月13日</a></blockquote>

# DBAは外部化できる

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

<blockquote class="twitter-tweet" data-lang="ja"><p lang="ja" dir="ltr">「蟲師」のような流れ者DBA。全国のRDBユーザを周期巡回<br>「すろーくえりはでてないかね」 <br>「狂った統計情報があらぶってないかね」 <br>「かすたむえすきゅーえるをせんじてあげよう」 <br>「一本いんでっくすを追加しておいたのですぐによくなる」 <br>というのを1ユーザあたり一泊二日。</p>&mdash; masuda kaz (@masudakz) <a href="https://twitter.com/masudakz/status/907003823457054720?ref_src=twsrc%5Etfw">2017年9月10日</a></blockquote>
<script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script>

# 隗より始めよ

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

<blockquote class="twitter-tweet" data-lang="ja"><p lang="ja" dir="ltr">こういったデータベースまわりの話が好きな人にもっと来てほしいですね。　：アプリケーションエンジニアのための実行計画 on <a href="https://twitter.com/Qiita?ref_src=twsrc%5Etfw">@Qiita</a> <a href="https://t.co/CZpRTqLWYo">https://t.co/CZpRTqLWYo</a></p>&mdash; 三木雅之 (@miki_cdo) <a href="https://twitter.com/miki_cdo/status/938638874229616640?ref_src=twsrc%5Etfw">2017年12月7日</a></blockquote> <script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script> 

<blockquote class="twitter-tweet" data-lang="ja"><p lang="ja" dir="ltr">うちのTさんは50歳代でコードを書いて技術成果を出し続け年収1000万超。<br>マネージャーなど管理系にいかなくてもプロ技術者としてのキャリアパスがあることを共有して増やしたい。</p>&mdash; 三木雅之 (@miki_cdo) <a href="https://twitter.com/miki_cdo/status/778184444389785600?ref_src=twsrc%5Etfw">2016年9月20日</a></blockquote> <script async src="https://platform.twitter.com/widgets.js" charset="utf-8"></script> 

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

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