とあるシステムでDBサーバの負荷を下げた話

はじめに

本記事では、とある塾さんのWebシステムで、システムが高負荷になっていた問題について、原因の特定から解決までのプロセスをまとめます。

いきなりまとめ

システム全体が重いとき、改善効果の大きい処理を探すには、各処理の「総処理時間」を集計することが非常に有効です。
今回は Apache HTTP Server のログに％D（リクエストに対する処理時間）を出力させることで、URLごとの処理を集計できるようにしました。対象の処理を特定し、インデックスを追加することで、DBの（ひいてはシステム全体の）負荷を下げることができました。

システム構成

そのプロジェクトは以下の構成で動作しています。

• Portal（ポータルサイト） → web1 / web2（ラウンドロビン）
• 基幹システム・バッチ、入退室管理バーコード読取 → web1
• web1：CPU x4 / MEM 32GB
• web2：CPU x1 / MEM 8GB
• DB：CPU x16 / MEM 128GB

【システム構成図】

課題

月1回程度の頻度でURL監視が障害を検知していました。
アクセスが重くなったり、タイムアウトしたりする現象がときどき起きていました。
その度に調査していましたが、なかなか根本解決には至っていませんでした。

障害対応の経緯

【過去の対応サマリ】

当初、アクセスが多いことが原因と考え調査を進めましたが、もっとアクセスが多い日でも正常動作している日があることが判明。アクセス数だけが原因ではないと判断しました。

アクセスが増える主な要因：

• お知らせメール送信後（メール受信した保護者からのアクセスが急増）
• 請求金額確定メール送信後（〃）
• 塾への入退室が多い日（入退室時にも保護者にメールが送られるため）

それでも障害発生

DBのCPU使用率が100%に達し、web1・web2ともに処理不能・httpd接続数超過が発生。ただしweb1・web2のCPUは50%以下であり、DBがボトルネックだろうと判断できました。web1, web2 はDBの処理待ちが多くて httpd 接続数がたまっていったと思われました。

DBのCPU使用率（改善前）100%近い時間帯が続いていた

ボトルネックの洗い出し

DBのボトルネック探しには、まず pg_stat_activity や postgresql-YYYYMMDD.logを使って重い処理を調査しました。

• pg_stat_activity :
  実行中のSQLを確認できる。
  特に、重い時間帯に確認すると、長時間実行しているSQLを確認することができる。
  参考→Qiitaの記事
• postgresql-YYYYMMDD.log :
  実行に10秒以上かかったSQLを記録するよう設定しており、長時間かかったSQLを後から確認できる。
  設定は postgresql.conf の log_min_duration_statement を使う。

判明した問題点（確かに問題だったが、結果的に根本解決に至らなかったもの）：

1. INHERITS で作成したテーブル（同期ログテーブル）のupdateが遅い（1〜4秒）
   ・ INHERITS = テーブル継承の仕組みで作成したテーブルのこと。
   ・ primary key である ID 指定で update しているのに遅かった。
   ・ この同期ログテーブルが2019年から蓄積されており、2000超のテーブルが作成されていた。
        これらに対しIDユニークチェックが走るため遅い（ID指定検索 × テーブル数）
   ・ ログ書き込みが遅いために同期処理に時間がかかり、lockテーブルのトランザクションが終わらない→
        pg_statistics の vacuum が進まない→ 悪循環
   ・ 古い service_sync_log を削除し、同期処理は安定しだしたが、DBは重いまま。
2. 「お知らせ機能」の検索が10秒以上かかる
   ・ 副問合せ同士の結合SQLが遅い
   ・ 検索画面のSQLのため修正が困難

などなど、vacuum のメモリ調整なども実施しましたが、全体的にまだ重い状態が続きました。
そこで、単体で重い処理ではないが、実行数が多いために負荷をかけている処理があるのではないかと考え、その集計方法を模索しました。

長時間かかる処理をhttpdログで探す

Apache のログに %D（リクエストに対する処理時間、百分の1秒単位）を追加することで、どのURLが時間を消費しているかを集計しました。ログフォーマットの設定はこのようになりました（%Dmi"が追加した部分）。

LogFormat "%h %l %u %t "%r" %>s %b "%{Referer}i" "%{User-Agent}i" %Dmi" combined 

※”mi” を付けたのは、grep で「7桁以上の処理時間」など検索しやすくするため

参考：Apache モジュール mod_log_config

しばらくログを記録し、URLごとに処理時間を集計した結果、最も時間がかかっていたURLが判明します。それは：

/api/absence/absence_contact/new_contact_arrived

教室スタッフ向けの「遅刻欠席連絡」メニューで、生徒からの連絡がないか1分おきにサーバへ問い合わせるポーリング処理でした。1日に10万〜30万回以上アクセスされており、午前は1回数百ms、午後は数秒かかることもありました。

処理時間集計結果

総処理時間は下記のようになりました。

※残念ながら、改善前の集計結果を手元に残しておらず、これは改善後の集計結果です。
それでも、 ~~/new_contact_arrived の処理時間の多さがわかります。
実は改善前はさらに1桁多い数値でした。

※余談ですが、同時に、フォントのダウンロードにも相当な時間がかかっていることもわかりました。
実体は9MBもあるフォントで、スマホなど狭い帯域からの通信で時間がかかったと思われます。
こちらはキャッシュ期間を延ばすことで対応しました。

SQL改善：インデックス追加

上記URLが実行するSQLは1つだけなので、すぐ特定できました。

対象SQL

SELECT /*%expand "ac"*/*
FROM absence_contact ac
INNER JOIN absence_contact_target act
  ON act.absence_contact_id = ac.id AND act.branch_id = /*form.branchId*/1
WHERE act.branch_id = /*form.branchId*/1
AND ac.created_at >= now() - INTERVAL '1 minutes' - INTERVAL '1 second';

このSQLを単体で実行すると、数百ミリ秒で返ってきますが、大量に実行されることでDBに負荷をかけていたのではないかと思われます。

EXPLAIN ANALYZE の結果（改善前）

「“explain analyze “ + 対象のSQL」で実行することで、下記のように、DBがどのようにそのSQLを処理したかがわかります。 ※実際にSQLを実行するのと同じ負荷がかかるので、高負荷時間帯は避けたほうがよい。

Nested Loop  (cost=1000.43..62297.41 rows=1 width=282)
             (actual time=311.648..311.648 rows=0 loops=1)
  ->  Gather  (cost=1000.00..42937.15 rows=2501 width=71)
              (actual time=0.293..199.553 rows=3112 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        ->  Parallel Seq Scan on absence_contact_target act
              Filter: (branch_id = 1)
              Rows Removed by Filter: 849718
  ->  Index Scan using absence_contact_pkey on absence_contact ac
        Filter: (created_at >= ...)
        Rows Removed by Filter: 1
Planning time: 1.086 ms
Execution time: 311.735 ms

問題点： absence_contact_target に対して Seq Scan（全件スキャン）が発生。約85万件をフィルタして3112件しか残らない非効率な処理になっていました。

EXPLAIN ANALYZE のチェックポイント

• Seq Scan がないか
•  actual time の増加
• rows × loops の大きさ
• Rows Removed by Filter が多すぎないか

インデックスの追加

EXPLAIN ANALYZE の結果から、branch_id での絞込み用にインデックスを追加しました。

CREATE INDEX absence_contact_target_idx2
  ON absence_contact_target USING btree (branch_id);

※テーブル absence_contact には branch_id のインデックスはあったのですが、absence_contact_target にはありませんでした。

EXPLAIN ANALYZE の結果（改善後）

Nested Loop  (cost=48.24..26935.31 rows=1 width=282)
             (actual time=13.344..13.344 rows=0 loops=1)
  ->  Bitmap Heap Scan on absence_contact_target act
        Recheck Cond: (branch_id = 1)
        Heap Blocks: exact=2719
        ->  Bitmap Index Scan on absence_contact_target_idx2
              Index Cond: (branch_id = 1)
  ->  Index Scan using absence_contact_pkey on absence_contact ac
        Filter: (created_at >= ...)
        Rows Removed by Filter: 1
Planning time: 0.255 ms
Execution time: 13.376 ms

Seq Scan が Index Scan に変わり、実行時間も 311ms → 13ms に短縮（単純計算で約24倍の高速化）。

インデックス追加の効果

効果は相当なものでした。

• DBの負荷が半分以下に低下
• SQLの実行速度が数十ms〜数百msに改善

グラフで如実に分かるほど改善されて、めっちゃうれしい！
これで、URL監視で通知が来ることもほぼ（※）なくなりました。

（※）Web2サーバのスペックが非力すぎて落ちることがありました。Web2サーバのスペックを 2xCPU + 16MB メモリに設定後、通知は4か月来ていません。

まとめ

ボトルネックの原因を特定するには、長時間かかる個別のSQLを探すだけでなく、総処理時間でも分析することが重要だと分かりました。

各サービス/レイヤでログに出しておくとよいと思います。

執筆者：U.N.(プロフィール)