0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

メール通知をDatadogダッシュボードに取り込む(DBロック監視編)

0
Posted at

はじめに

MySQL のレコードロックを維持し続ける長時間トランザクションを監視し「メール通知」している環境があります。このメールを Datadog に取り込み、ダッシュボードで可視化することで、どのセッションが長時間ロックを保持しているかを一目で把握するための再現テストをしました。

設定手順は省き、メール本文をどうやってDatadogのログに変換したか を書きます。記事中の数値・名称はすべて架空のものです。図は再現のための検証環境の画面です。

背景

レコードロックはなぜ残るのか

筆者はアプリのプログラマーとしてデータベースへアクセスすることはあるものの、DBアドミニストレーターとしての専門知識は足りないので下記は一夜漬け程度の知識とご了承ください。

MySQL(に限らず他のDBも同様とのこと)は、UPDATE や DELETE、SELECT ... FOR UPDATE を実行すると、対象の 行(レコード)に排他ロック をかけます。このロックは、トランザクションが COMMIT か ROLLBACK で終わるまで外れません。

ふだんは数ミリ秒で終わるので問題になりません。ところが、アプリが トランザクションを閉じないまま 接続を残すと、ロックも残り続けます。

  • 例外処理の漏れで、COMMIT / ROLLBACK を通らずに処理を抜けた
  • 自動コミットを無効にしたまま、更新後の確定を忘れた
  • バッチが途中で止まったが、コネクションプールが接続を保持し続けている

すると、同じ行を更新しようとした別の処理が待たされ、やがてタイムアウトします(既定では50秒)。

想定する環境(再現した環境)

複数のアプリが共通で使う MySQL があり、ときどきこの「ロックを持ったまま残るトランザクション」が発生する。原因のアプリはまだ特定できていない。

そこで DB サーバーの cron で1時間ごとに検査し、開いたまま(RUNNING)でレコードロックを持つトランザクション があれば、メールで通知しています。検査は、トランザクションの一覧(information_schema.innodb_trx)と、ロックの一覧(performance_schema.data_locks)を突き合わせるものです。

なぜDBモニタリングじゃないのか

DBサーバーに Datadog Agent をインストールしておらず、従来型IT監視のまま、Datadog の AIOps(Bits AI Investigator や Bits AI Chat など)を活用してみたいという理由です。幸い、DBセッション情報をメール通知しているので、メール情報を Datadog に取り込んでみます。

課題

メールを受信したら下記のように判断します。

  1. 複数の受信メールを見比べる
  2. 同じトランザクションが2回、3回と続いていたら 長時間トランザクションが解放されないと判断し、プロセスを KILL することを検討します

これを一日当たり約20通のメールに対して目視検査します。カイゼンしたい苦労(Toil)です。

解決の方針

Datadog Agent をインストールしない。つまりDBモニタリングを使わず、メール通知をそのまま Datadog に送る ことにする。Datadog には、メールを受信してイベントに変換する「Events with Email」があります。

やむなく工夫したこと

メール本文を Datadog の ワークフロー でログに分解する。

メールはイベントになるが、本文の中身では集計できない

メールは件名がイベントのタイトル、本文がメッセージになります。ところが本文は ただの文字列 で、接続IDやトランザクションIDで集計(group by)できません。

図1: Datadog に届いた通知メール(イベント)
図1: Datadog に届いた通知メール(イベント)

パイプラインでは解決できなかった

Datadog の標準機能で解析したかったができない。

方法 結果
Logs Pipeline メールはイベントなので、ログパイプラインを通らない
Events Pipeline* 1イベントにつき1回しか一致しない。
1通に1〜5行あるトランザクションを、行ごとのレコードにできない

*Events pipeline メニュー遷移: Event Management > Settings > Pipelines

代案: Workflow Automation で「1行 = 1ログ」に分解する

そこで、Workflow Automation を 10分毎 に動かし、次の処理をさせました。

  1. 直前の10分間に届いたメールイベントを API で取得
  2. JavaScript でメール本文にある複数行を、行単位に分解
  3. 分解した1行を1件のログとして Logs に送る

図2: メール本文をログに分解するワークフロー
図2: メール本文をログに分解するワークフロー

できあがったもの

入力: メール通知

メール件名に「データセンターとインスタンス」、
メール本文に「トランザクションの情報」が1行または複数行、記載されます。

メール件名[DB Report:D70412]

DBロック監視レポート(自動送信)

CONN_ID    TRX_ID     USER        DATE        TIME1       TIME2       SCHEMA     DIGEST              LOCK_MODE        STATE
2081       4219375    shop_app    20260415    11:52:30    13:00:00    orders     3f9a1c0b7e2d4a65    X,REC_NOT_GAP    RUNNING

CONN_ID    TRX_ID     USER        DATE        TIME1       TIME2       SCHEMA     DIGEST              LOCK_MODE        STATE
4417       4219102    pay_app     20260415    10:41:12    13:00:00    payroll    b5e8d2a9c1f07364    X,REC_NOT_GAP    RUNNING

▼メール本文に記載の[トランザクション情報]の読み方

列 内容
CONN_ID 接続ID(SHOW PROCESSLIST の Id。KILL の対象)
TRX_ID InnoDB のトランザクションID
USER / SCHEMA 接続ユーザー / ロックされた行のスキーマ
TIME1 / TIME2 トランザクションの開始時刻 / 検査時刻
DIGEST 実行中の SQL のダイジェスト(先頭16文字)
LOCK_MODE X,REC_NOT_GAP = 行そのものへの排他ロック

メール本文から生成されるログ

上記サンプルのメールには 2件のログが記載れている。分解して生成するログ1件目は下記。

{
  "service": "mysql",
  "message": "D70412 CONN=2081 TRX=4219375 USER=shop_app SCHEMA=orders DIGEST=3f9a1c0b7e2d4a65 HOLD=67.5min",
  "db": { "datacenter": "D7", "instance": "D70412" },
  "trx": {
    "conn_id": 2081, "trx_id": 4219375, "user": "shop_app", "schema": "orders",
    "digest": "3f9a1c0b7e2d4a65",
    "key": "D70412:2081-4219375"
  },
  "lock": { "hold_minutes": 67.5 },
  "checked_at": "2026-04-15T13:00:00+09:00"
}

図3: メール本文の1行が1件のログになったところ
図3: メール本文の1行が1件のログになったところ

出力: ダッシュボード

ダッシュボードは主に3つのグループで構成する。

グループ 内容 データ
A メール受信 メール数、データセンター別の推移、インスタンス別の件数、最新メール イベント
B トランザクションの状態 継続中のトランザクション、ロック保持時間、ユーザー × スキーマ、SQL、判定を誤りやすいケース ログ
C 取り込みの健全性 メール数と取り込んだ数の比較、解析できなかったメール イベント + ログ

図4: ダッシュボード全体
図4: ダッシュボード全体

ダッシュボードの読み方

まず見るべきは「継続中のトランザクション」

直近120分のトランザクションを1行ずつ並べた表です。
監視運用者は この表だけで kill 接続を切断し、トランザクションをロールバックを判断できるようにする。

列 意味 色
観測継続時間 同じトランザクションが最初に現れてから最後に現れるまでの時間(分) 30分以上 オレンジ(= 2回連続)
60分以上 赤(= 3回連続)
推定ロック保持時間 トランザクションの開始から最後の検査までの時間(分) 60分以上 オレンジ
90分以上 赤
観測回数 何回の検査で現れたか 参考
DIGEST の種類数 途中で SQL が変わったか 2以上 オレンジ
  • 観測継続時間に色が付いた行がプロセスkillする候補 で、赤は優先度が高い
  • 観測継続時間が0の行は、まだ1回しか現れていないトランザクション

図5: 継続中のトランザクション。黄色がエスカレーション候補

図5: 継続中のトランザクション。黄色がプロセスkill候補

  • 上の2行は、同じインスタンスの2つのトランザクションが 3回連続(観測継続時間60分)で現れていて、赤。エスカレーションの優先候補です。1行目はロックを213分以上持ち続けています
  • 3行目はまだ1回しか現れていません(観測継続時間0)が、トランザクションの開始から62分たっていて、ロック保持時間がオレンジです。次の検査でも現れたらエスカレーション候補になります
検査時刻      20:30        21:00        21:30
              │            │            │
1回目だけ     ●                                   継続 0回  0分
              
2回連続       ●────────────●                      継続 1回 30分以上(オレンジ)
              └─── 30分 ───┘

3回連続       ●────────────●────────────●         継続 2回 60分以上(赤)
              └─── 30分 ───┴─── 30分 ───┘
              └───────── 60分 ──────────┘

● = その検査でメールに現れた   観測継続時間 = 最後の ● − 最初の ●

傾向を見る

ダッシュボードで可視化できたのち、Datadog Bits AI Chat もしくは Datadog MCP Server を使って自然言語で調査・分析できることを期待する。

  • インスタンス別の最大ロック保持時間: 線が右肩上がりなら、ロックが伸び続けている
  • ユーザー × スキーマ: どのアプリがどのスキーマでロックを持ちやすいか。原因のアプリを探す手掛かりになる
  • ロックを持つ SQL(DIGEST): 同じ SQL が繰り返し現れていないか。トランザクションを閉じ忘れている処理の当たりを付ける

モニタリングの仕組みが止まっていないか

メール数と取り込み数 は3つの値を積み上げグラフで表示しています。

  • 水色(上) : メール(Datadog に届いたメールの数)
  • 青色(中) : 取り込んだメール(ログに分解できたメールの数)
  • 紫色(下) : 取り込んだ行(ログの件数)
    水色と青色のグラフ高さが同じなら、届いたメールが全て1回ずつログに分解されていて、取りこぼしも重複もない。紫色は1通のメールに複数ログが記述されているログ数を意味する。
    図6: メール数と取り込み数がそろっている
    図6: メール数と取り込み数がそろっている(水色=青色)

まとめ

  • メール通知は、Datadog に送れば集計・可視化できる
  • メール本文をログ等へ分解するにはワークフローでスクリプト実行 することも候補
  • ログ・メトリクスへ変換できれば、ダッシュボードに一目で把握できる情報を配置できる

ダッシュボードで可視化できたので、次はAIを使った調査・分析に取り組む予定です。

0
0
0

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
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?