LoginSignup
7
5

More than 5 years have passed since last update.

PostgreSQLAdvent Calendar 2016Day 23
@masudakz(増田 和弘)

pg_stats_reporter をしくじった話

Last updated at Posted at 2016-12-22

この記事は、PostgreSQL Advent Calendar 2016 の 12/23 に入る記事です。

株式会社ジャストシステムのサービス運用で使っている pg_stats_reporter についてしくじった話を書きます。
その前に、2016年の自分の振り返りも兼ねて、pg_stats_reporter について、ここで書くことにしたいきさつを軽く。

1月　技術内閣の始まり

CDOに招集されてデータベース大臣になりました。

CDOの意図はこちらのSELEKさんの記事で。

事業は個人向けだけでなく、民間企業、メディアや病院、自治体といった法人向けまで、幅広く展開しています。そうして事業が多様になると、事業ごとに使う技術もバラバラになり、組織は縦割りになっていきます。そのような環境の中で、どう全社的に横連携するか。技術の横連携を強化するため「内閣」を発足

若い人たちがQiita:Team導入頑張って 試用が始まったので、枯れ木も山の賑わいと「PostgreSQLアンチパターン」の週刊連載をしていたら、CDOに目をつけられたんだと思っています。

5月　pg_stats_reporter読影会

大臣といっても、個人ミッションはそのままで、大臣業務を上乗せなので、そんなに工数割けるはずもないです。自動化・省力化、属人性除去して別の人に肩代わりしてもらって時間をひねり出す、というのはきれい事で、実際は優先度の低い作業の切り落としです。技術的負債の積み上がりを看過するとかね。後が怖いことになるので、15-20%が限界。そしてアラカンの俺の手はそんなに速くは動かない。なるべく楽して成果を出したいという横着心で そういう制約の中で組織のために何ができるか、どうやって自分のスキルを伝授できるか、考えてました。

ある日、「このサービスの性能問題なんとかなりませんか」という、大臣SOSが来て、他サービスのpg_stats_reporterを見て、読影会を思いつきました。
準備作業なしで運用環境のヘルスモニター、pg_stats_reporter やmuninの画面を一緒に眺めて、どこに注目しているのか、ここの数値からどんな兆候を読み取るのか、どうサービスを守るのか、勘所を各サービスの運用担当みんなで共有しようぜというもの。

読影会以外のDB大臣活動をtweetまとめはこちら。http://qiita.com/masudakz/private/aa9920d545f6b626910e

9月　PostgreSQLアンカンファレンス

読影会に手応えがあったので、大臣ミッションの「社外にもアウトプット」を、第8回 PostgreSQLアンカンファレンス＠東京 9/10@市ヶ谷でやってきました。

  • 公式ページ
  • 初参加で知名度なくて、ほとんどのオーディエンスを並行した桑田さんの「とあるサービスでのパフォーマンス障害とその対策を赤裸々に報告」にとられてしまいました。でも泣かない。
    • 直接面識どころか、TwitterでもSlackでも絡んだことのある人は当時一人もいなかった。
  • 聞いてくれた人からは暖かい励ましのコメントをもらいました。

アンカンファレンスは、発表予定者が突然都合悪くなっても誰にも迷惑かける感じがないのもいいところ。また行きたい。

他サービスの性能問題をなで切り

11月　通用しないパターン襲来

pg_stats_reporterを診てください、ときたら「秒で成果をアピールできるチャンスタイム」と増長していました。そんな11月も終わりかけの夕方にそれは来た。

甲「tomcat全部からAlert大量に出てます」
乙「DBServerが息してない？」
丙「運用環境でDB接続エラーが発生してます Could not open JDBC Connection for transaction」
乙「書き入れ時にやっべー」

調査・分析を開始したときには、Alert止まってサービスは正常化していましたが、再発条件を確定し、対策をうたないといけません。

DBServerの一時的なブラックアウトなので、いつものように pg_stats_reporter をいつもの順番で見始めました。

  1. Long Transactions
    容疑者なし
  2. Statements
    容疑者なし　いつもの見慣れた状況。time/call は1位でも30msec、2位以下は10msec未満でやるべきチューニングはもうやった（と思ってた）
  3. Heavily Accessed Tables
    seq_tup_read:Seq.Scan累計行数の上位もいつものメンツだ。ごく小さいTable群で参照頻度が高いものが上位に来ているので問題ない。容疑者ではない。

いままで通じてきたパターンが使えない。どうしよう。

仮説を疑え

一時的（瞬間的）なDBServerブラックアウトに遭う度に、対策として潰してきたのはSeq.Scanというここ数年の運用経験から、やはり見直すとしたらHeavily Accessed Tablesだろうと。

アンカンファレンスで発表したスライドから

"Heavily Accessed Tables" で一番注目しているのは"seq_tup_read"
tup_per_seq が大きくてもアドホックなSQLによる単発なら性能問題にはならない。セキュリティ案件にはなるかも。

seq_scans:スキャン回数が極端に少ないところなら、tup_per_seq:行数/スキャン回数が大きくても、気にしていなかった。

tup_per_seqに注目すると、これまでチューニングの対象にしていなかったTableが浮上。
入会前の資料請求処理で使うTableでした。seq_scans:回数は、ほかより何桁も小さい。それはそうです。入会前資料請求はほとんどの人がサービスライフタイム中に1回かぎり。入会後に使うAPIは1日に何十回もあって、ほぼ毎日継続的に呼ばれるわけですから。そんな低頻度APIは性能検証シナリオにも入れてない。

でも、これがあやしい。tup_per_seqの行数から、30msecとかで済みそうな気がしない。Long Transactions にも Statements にも出てないけど限りなく匂う。

現場100回（実際は1回）

リモートのWebUIでスマートに監視できる pg_stats_reporter を離れて、PostgreSQLの出力しているログを直接見に行きました。
このへんが老兵の使いどころ。pg_stats_reporter 導入前から、PostgreSQLの性能障害トラブルシュートしていたので、ひとつ古い手も抽斗に入っている。

期間: [0-9]{3,5}\.[0-9] の正規表現検索で、100msec超のSQLを引き出すと、やはり資料請求処理で使うTableのそれが、出てくるじゃないですか。ブラックアウト前にも来ている。

SQL確定、API確定、不足index確定。index追加して緊急対策終了。

機動警察パトレイバー２の太田のセリフを思い出すなあ。
訓練生「あの、何故マニュアルで操作を。ＦＣＳを使用してロックオンすれば、９８パーセントの命中率と聞いておりますが・・・」
太田「そのＦＣＳが、故障したらどうする・・！」
訓練生「はあ？　でもレイバーによる警備活動はペアーが原則ですし」
太田「その僚機が、行動不能だったら・・！」
訓練生「いやしかし、そんなケースは万に一つの・・・」
太田「その“万に一つ”に備えるのが、俺達の仕事だろうが、このボケェェ！！グランド２０周、行け！」

今後の課題

サービスライフタイム中に1回かぎりのAPIでも性能障害を引き起こす段階までこのサービスが成長したということです。めでたい。

実際、過去最高の資料請求実績でした。
DBAにとっては「tup_per_seq が大きくても単発なら性能問題にはならない」なんて、ヌルいことはいってられなくなって、行数の大きくなるところは全パターンのSeq.Scanを潰して回ることになります。後継DBAがんばれ。

pg_stats_reporter についてのしくじり先生

なぜ例のSQLがStatementsに出てこないのだろう？　なにか足切り設定があるのかな？

  • 実はマニュアル読んでいなかった
    • そんなんでアンカンファレンス行ったのかい！
    • 設置を Ops側の人がやってくれたので、Dev側はマニュアルも見ないでWebUIで使いはじめてそのまま
    • それで十分使えるいいツールです。各項目に Information のポップアップも実装されているし

初めてマニュアル読んでも、設定としてはDB接続先くらいで、Statementsの足切り設定なんてないです。
それはそうだ、これはWeb可視化ツールで、情報収集・集計は、pg_statsinfo

マニュアル読んでなかったので、このアーキテクチャも知らなかった。

pg_statsinfo のマニュアルまで来て、それっぽい記述を発見。

取得できる統計情報一覧
- 実行回数、累積実行時間の多いSQLと関数。

calls, total_time で足切りがあるっぽい。これで、例のSlow Query が見えなかったんだろう。

設定ファイル
追加設定項目
pg_statsinfo.stat_statements_max default:30 pg_stat_statementsで収集する情報数の上限

あった、これだ。運用の postgresql.conf を確認すると、必須設定項目だけ設定していて、上記を含む追加設定項目は無かった。default の 30のままだ。

そしてクエリの統計情報の元ネタはpg_stat_statementsの提供するpg_stat_statements ビューになっていることもわかった。

そちらにも記録するSQL文の最大数設定がある。

pg_stat_statements.max
これを超えて異なるSQL文を検出した場合は、最も実行回数の低いSQL文の情報が捨てられます。
9.3 だとデフォルト1000, 9.6 だと 5000

ちょっと覗いてみる。

postgres=# select dbid,query,calls,total_time from pg_stat_statements order by calls limit 1;
 dbid  |                 query                  | calls | total_time
-------+----------------------------------------+-------+------------
 16961 | UPDATE                                +|     1 |       0.11

postgres=# select count(*) from pg_stat_statements;
 count
-------
   897
  • このサービスの現状は全部のStatementsが欲しければ897以上必要
  • pg_stat_statements.maxは、9.3デフォールトの1000でも足りてそう。
  • VIEW pg_stat_statements には calls=1 まで入っている（今のところ）。

pg_stats_reporter 関連設定の対策

  • postgresql.conf に pg_statsinfo.stat_statements_max = 1000 を追記
    • もちろん運用の前にステージングで検証
    • pg_statsinfo の snapshotサイズは大きくなるはず。5分に1回を1週間分保存しているから、2016倍で効いてくる。それでも微々たるものだとは思うけど。

この修正前に何かあったときは、PostgreSQLのログよりはるかに見やすい、VIEW pg_stat_statements を見に行くこと

まとめ

  • pg_stats_reporter はいいぞ
  • マニュアルは読め
  • 依存ツールのマニュアルも全部読め

今回の問題は、pg_statsinfoマニュアルにちゃんと書いてあります。

インストール手順 - 設定ファイル - クエリの統計情報の取得設定

また、必要に応じて設定ファイルに下記のパラメータを設定してください。
- pg_statsinfo.stat_statements_max
- pg_statsinfo.stat_statements_exclude_users

そう、 必要に応じて

7
5
2

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
7
5