【やらかしアドカレ】あの日見た障害の原因を僕達はまだ知らなかった。

本記事は 本番環境などでやらかしちゃった人 Advent Calendar 2023 20日目です

旧タイトル: あの日見た障害の原因を僕達はまだ知らない。

はじめに

こんにちは！現実逃避で手間のかかる料理を作る @come25136 です！！
最近手がけたサービスで色々やらかしまして、今回はそれらを何個かピックアップしてご紹介します。
この記事では、なぜそのような事が起こったのか、そしてどのように対処したのかをお話しします。

一応補足

詳しく話書いている部分がありますが、これらは私が開発しているサービスであり全ての権利が私にあるので、しょっぴかれる心配はありません。

サービスについて

norumes Cloudという交通系APIを作っています

このサービスはNest.js, Redis, PostgreSQLで作られていて、停留所検索や時刻表生成(OD検索)などを提供しています。

活用事例

熊本市内バス会社5社による時刻表作成サービス"My バス時刻表 in 熊本"に採用され、バスセンターや一般ユーザー宅など、幅広い場所から使用されています。
ニュース: https://www3.nhk.or.jp/lnews/kumamoto/20231016/5000020383.html

【第一章】データベースの危機

サービスローンチから数カ月後...
顧客「レスポンス遅いんだけど」
自分「😇」

原因を調査すると、データベースに問題が発生していることが判明。一部のSELECTクエリが10倍程遅くなっていました。
そしてこの現象はCPUを圧迫し、他の処理にまで影響を及ぼす非常にクリティカルな問題でした。

原因

オプティマイザ「データベース完全に理解した👍」^[1]
これに尽きます。

え、オプティマイザ？と思う方が大半かと思います。
多くの人は適切にIndex張られてない問題にn回ぶち当たっているので無理もありません。
（私もその一人で、「どうせIndexだろ」と余裕ぶちかまして3ヶ月程溶かしました）

オプティマイザが狂った起因

norumesは定期的にデータ更新を行っているのですが、これが起因でした。

データ更新は追記型アーキテクチャを採用しており、INSERTとDELETEを用いて更新を行っています。
また、上記の通りIndexは適切に張られていて開発中は快適に動作しており、dumpデータを使っても再現しませんでした。

ではなぜ遅くなったのか...
データ量が変動したことにより、オプティマイザが 「フルスキャンした方が早いやろ😉」と判断するようになったからです。

実際そんなことはなくインデックスに沿えば最短検索出来るのですが、一度狂うと元に戻ってくれず困りました。

解決策

PostgreSQLでの解決策は4つあり、

1. Indexの組み方を変え、オプティマイザを誘導する
2. ヒント句を使う(pg_hint_plan)
3. 統計情報を保存し、それを使い回す(pg_dbms_stats)
4. GUCパラメーターを変える

多くの方は(1)で事足りると思います。

しかし今回は(1)では力及ばず、(2)(4)を採用しました。^[2]
※PostgreSQLは標準でヒント句を扱えず、pg_hint_planを導入する必要があります。

こちらは実際に使用しているヒントで、Nested Loops以外許さない感じのヒントになっています。

Set(join_collapse_limit 10)
Set(enable_bitmapscan off)
Set(enable_hashagg off)
Set(enable_hashjoin off)
Set(enable_indexscan on)
Set(enable_indexonlyscan off)
Set(enable_material off)
Set(enable_mergejoin off)
Set(enable_nestloop on)
Set(enable_seqscan off)
Set(enable_sort on)
Set(enable_tidscan off)

NestLoop(...)
etc...

SetはGUCパラメーターを変更する命令で、NestLoopがヒント句です。
いずれもpg_hint_planの機能です。

ヒント句導入後

フルスキャン現象は無くなり、CPUを圧迫することも無くなりました。
オプティマイザなんて要らんかったんや😎

余談

この現象ですが、解決するまで何度も再発させてしまいました。
最初は原因が分からず、データベース初期化するなど本番では絶対ありえない事もしました。
二度あることはn度あります。

【第二章】メンテが終わるとどうなる？

「知らんのか」「メンテが始まる」^[3]

特定の条件下でフルスキャン現象が再発しました。しちまいました。なんでや。
根本原因の改修するのも重要ですが、この問題はCPUを圧迫するので先にタイムアウトを設定します。

タイムアウトの設定

norumesではPrismaを採用しており、タイムアウトの設定は容易に出来ま...せんでした。なんでや。

偉い人は言いました...
　　タイムアウトが無ければ
　外部から殺せばいいじゃない
...と。

というわけで代わりにWDT(Watchdog timer)を導入します。
【PostgreSQL】実行中のクエリを調べる方法からクエリを拝借し... 書いたものがこちらになります。

const processes = await this.database.getClient().$queryRaw<RemapColumns<typeof SelectColumns>>`
  SELECT
    procpid,
    start,
    EXTRACT(EPOCH FROM now() - start) AS lap,
    current_query
  FROM
    (SELECT
      backendid,
      pg_stat_get_backend_pid(S.backendid) AS procpid,
      pg_stat_get_backend_activity_start(S.backendid) AS start,
      pg_stat_get_backend_activity(S.backendid) AS current_query
    FROM
      (SELECT pg_stat_get_backend_idset() AS backendid) AS S
    ) AS S
  WHERE
    current_query <> ''
    AND start IS NOT NULL
`

for (const process of processes) {
  const query = process.current_query.trim()

  if (query === '<command string not enabled>' || process.lap === null) continue
  if (query.startsWith('SET ')) continue // 多分DBeaverからの接続
  if (query.startsWith('SHOW ')) continue // 多分DBeaverからの接続

  if (checkInterval <= process.lap) {
    try {
      const variables = {
        pid: process.procpid,
        startAt: process.start?.toISOString(),
        query: query,
      }
      this.logger.warn('Long query detected.', variables)
      this.logger.debug('Killing process', variables)
      await this.database.getClient().$queryRawUnsafe(`SELECT pg_terminate_backend(${process.procpid})`)
      this.logger.log('Killed process', variables)
    } catch (err: any) {
      this.logger.error('Failed to kill process', err.stack ?? err.message)
    }
  }
}

WDTということで特定のクエリに絞らず活用性を持たせました。

活用性を持たせた結果

失敗した失敗した失敗した失敗した失敗した^[4]

実はこの「実行中のクエリを調べるクエリ」とんでもない物まで拾ってしまうのです。
それはPostgreSQLではお馴染みautovacuumで、autovacuum: ANALYZE public.tableといったクエリを拾ってきてしまいます。

kill→autovacuumを永遠と繰り返していたわけですね。

幸いにも4日程で気づき修正しましたが、危うくDBを壊しかねない事態に陥っていました。

【第三章】暫定対処だけで終わる奴いる？

いねえよなぁ！！？^[5]

第一章のクエリにSet(join_collapse_limit 10)と書いていたのですが、これでは不十分なのです。
そう、(恐らく)こいつが再発した原因です。

join_collapse_limitとは何か

JOINの平坦化数を決めるパラメーターなのですが、ざっくり書くとJOIN順をオプティマイザに任せず書いた順でJOINしてくれるようにするものです。
※join_collapse_limit = 1の場合

これが10になっている事でオプティマイザが考える手順が増えてしまい、再発したというわけですね。(多分)
実際、Planning Timeが大きい事から可能性は高いです。

【最終章】あの日見た障害の原因を僕達はまだ知らない。^[6]

第三章の自信の無さから察してほしいのですが、 まだ根本解決していません。
というのも開発時間の問題なので年内に解決したいところ...

2024/1/16 追記
多分解決しました
https://zenn.dev/come25136/articles/071702cff5f27d

おわりに

やらかした分だけ強くなれるよ^[7]

余談

このサービスはオンプレで動かしており、暴走と騒音(冷却ファン)が比例するので最初は音で「あっ障害かな」みたいな感じでメンテしてました。
風量MAXのドライヤーが急に増えるのをイメージしてもらえれば分かりやすいと思います。

この辺りの話もいずれ書きたい。

• オンプレを採用した理由
• アラートではなく騒音で気づいた理由
• ProxmoxでVM建てたりライブマイグレーションする

宣伝

現在、転職活動をしています😎
基本的に興味あればなんでもするのでお気軽にメッセージください！
気軽にカジュ面しましょ～～
※DM閉鎖してるのでメンションください
https://twitter.com/come25136

脚注

1. https://developers.freee.co.jp/entry/understand-of-perfect-understanding#:~:text=ダニング・クルーガー効果を「完全に理解する」

2. 本当はpg_dbms_statsを採用したかったのですが、pg14までしか対応していなかったため採用しませんでした。(pg15を使用)

3. https://dic.pixiv.net/a/知らんのか

4. https://dic.nicovideo.jp/a/失敗した失敗した失敗した失敗した失敗した
   あたしはstgすっ飛ばしてprodリリースした(本番しか再現しないから)

5. https://dic.pixiv.net/a/いねえよなぁ

6. https://ja.wikipedia.org/wiki/あの日見た花の名前を僕達はまだ知らない。

7. https://dic.pixiv.net/a/涙の数だけ強くなれるよ