はじめに
自習環境でPDF出力機能を検証していたときのことです。
ある日、突然処理が終わらなくなりました。
しばらく待っていると、画面には 504 Gateway Timeout。
「メモリが足りないのか？」
最初はそう思いました。
メモリを疑う
Azure App Service のメトリクスを確認。
メモリ使用率はおよそ45％。
上限に張り付いているわけではありません。
念のため、コンテナ内でも確認しました。
cat /sys/fs/cgroup/memory/memory.limit_in_bytes
表示された値は、実質無制限に近い数字。
少なくとも、メモリ制限で落ちているわけではなさそうでした。
ではなぜ504が出るのか。
「タイムアウトかもしれない」
処理時間を見直す
ログを丁寧に追っていくと、リクエストが300秒以上かかっていることが分かりました。
これなら504になってもおかしくありません。
問題はメモリではなく、単純に「遅い」ということでした。
SQLを疑う
PDF出力処理では、データを取得してループしながら帳票を組み立てています。
もしかして、特定のSQLが遅いのでは？
そう思ってAzure Database for PostgreSQLを確認しました。
しかし、Query Storeは無効。
さらにサーバーパラメータを見ると、
log_min_duration_statement = -1
遅いSQLは一切ログに出力されていませんでした。
見えないものは、直せない。
まずは可視化から
log_min_duration_statement を 1000 に変更しました。
これで1秒以上かかったSQLがログに出ます。
その状態で、問題のPDF出力をもう一度実行。
Azureポータルのログを開き、息を詰めて確認しました。
出てきました。
duration: xxxx ms
同じSELECT文が何度も並んでいます。
そして、1回あたりも決して軽くない。
ようやく、ボトルネックが見えました。
インデックス不足
検索条件に使っているいくつかの列があります。
しかし、それらをまとめてカバーするインデックスはありませんでした。
複合インデックスを追加しました。
ロック影響を避けるため CONCURRENTLY を使用。
そして再度実行。
結果は
約10秒 → 約2秒。
はっきり分かる改善でした。
学び
今回の一件で感じたことがあります。
最初にメモリを疑ったのは、完全に思い込みでした。
504が出ると「リソース不足」と考えてしまう。
でも実際は、単純なインデックス不足。
そして何より大きかったのは、
推測ではなく、ログで確認したこと。
log_min_duration_statement が -1 のままだと、何も見えません。
見えないまま議論しても前に進みません。
まずは可視化。
そこからボトルネックを特定し、最小限の対処をする。
遠回りに見えて、それが一番早いと感じました。
おわりに
今回の問題はインデックスで改善しました。
ただし、ループ内でのクエリ実行は構造的な負荷を生みやすい部分でもあります。
N+1の可能性も含め、設計レベルでの見直しも今後の課題です。
それでも、504の正体を一つずつ剥がしていく過程は、とても良い学びになりました。
エラーの裏には、必ず理由がある。
焦らず、数字を見て、順番に潰す。
改めてその大切さを実感した出来事でした。
