Mongo CPU 過負荷調査およびログ#
作成日:2021 年 6 月 22 日午後 5 時 52 分
現象#
本番環境のメインデータベースで、周期的に(04:05、04:15、07:05、07:15、11:05)および非周期的に(04:15-04:30、11:05-11:15)CPU 使用率が 5 分間で 80%を超える現象が発生しています。
- CPU の過負荷は周期的であり、連続して発生しないため、問題が定期的なタスクに起因している可能性が高いと考えられます。
- AWS EC2 上の警告時間に基づいて関連する定期的なタスクを絞り込むことができます。
CPU 過負荷の客観的な原因#
フルテーブルスキャン(collection scan)#
- 何をするのか:COLLSCAN は、テーブル全体をスキャンする高 CPU 消費操作であり、テーブル内またはデータベース内のすべてのレコードを条件に基づいてフィルタリングします。プロファイルコレクションまたはログで COLLSCAN キーワードを見つけ、この操作が頻繁に行われる場合は、クエリフィールドにインデックスを作成して最適化する必要があります。
- どのように特定するか:プロファイルの planSummary パラメータを使用して、遅いクエリのフルテーブルスキャンが発生しているかどうかを判断できます。
- どのように対処するか:適切なインデックスを作成します。
適切でないインデックス#
- 何をするのか:適切でないインデックスは、クエリの実行時に多くのインデックスをスキャンすることで CPU の高い負荷を引き起こします。
- どのように特定するか:system.profile またはクエリプランの planSummary 値が IXSCAN であることを確認することで、インデックスクエリを特定し、keysExamined に基づいてインデックスが適切かどうかを確認できます。
- どのように対処するか:適切なインデックスを作成します。
大量のデータのソート#
- 何をするのか:クエリのソート要求がインデックスを使用して完了できない場合、Mongo はデータをメモリに格納してソートします。データ量が多い場合、CPU 使用率が高くなります。
- どのように特定するか:system.profile コレクションで SORT キーワードを見つけた場合、インデックスを使用してソートを最適化することを検討できます。クエリにソート段階が含まれている場合、system.profile の hasSortStage フィールドは true になります。
- どのように対処するか:ソート用のインデックスを作成します。
サービス能力の超過#
- 上記の問題をすべて調査し、すべてのクエリとインデックスが適切である場合、サービスの容量がビジネスの規模に追いついていないことを意味します。
- この場合、構成のアップグレードを検討する必要があります。
Mongo での適切なインデックスの作成方法
- ドキュメントをよく読む([https://docs.mongodb.com/manual/indexes/])
- ディスティンクト度が高い:distinct value count /total value count
- Null 値がない:null はインデックスを作成しない
- 更新やクエリフィルタに頻繁に使用される
- 昇順または降順:
- 単一フィールドインデックスでは、昇順と降順の効果は同じです。なぜなら、Mongo のインデックスはソートされた状態で上下に移動してクエリを実行するからです。
- 複合インデックスでは、2 番目のインデックスフィールドの昇順または降順がクエリの効果に影響を与えます。たとえば、2 番目のフィールドが注文時間である場合、降順インデックスは注文をより速くロックすることができます。
- 盲目的にインデックスを作成しないでください。インデックスには作成および挿入時のコストがかかります。
- このトピックは非常に広範であり、後で詳しく説明します。
上記の問題を監視および検出する#
CurrentOp(現在の操作情報)#
ピーク時に、db.currentOp()を使用して過負荷の DB を状態チェックし、返される値の意味を確認します([https://docs.mongodb.com/manual/reference/command/currentOp/#currentop-output-fields])。
プロファイラ(パフォーマンス分析ログ)#
- Mongo クエリのパフォーマンスログ収集機能は、デフォルトでオフになっています。データベースのパフォーマンスにわずかな影響があるため、プリプロダクション環境でのみ有効にすることをお勧めします。
- 主な機能は、データベースコマンドとその実行情報を、各 db の system フォルダの profile コレクションに保存することです。このコレクションのサイズは固定であり、設定されたサイズを超えると古いログが自動的に削除されます。現時点では、最大で最新の 950 件のレコード(大規模な遅いクエリに感謝)を保存できます。
- プロファイラは、currentOp のログバージョンです。両者の返されるパラメータは完全に同じです。
- プロファイラは、db.setProfilingLevel(level)を使用して設定できます。level には 3 つのレベルがあります:0(オフ)、1(操作の実行時間がslowms閾値に基づいてフィルタリングされます。slowms は操作の実行時間をミリ秒単位で指定します)、2(すべての操作ログを記録します)。
- db.getProfilingStatus()を使用して、現在の db のプロファイラの設定を取得できます。
いくつかの重要なパラメータに注意する#
secs_running
- 操作の実行時間、秒単位
microsecs_running
- 操作の実行時間、ミリ秒単位
- 遅いとはどのくらいですか?
- Mongo のデフォルトでは、100ms 以上のクエリは遅いクエリと見なされますが、実際の状況では、30 秒のフルテーブルスキャンクエリがあります。したがって、最初に 200 に設定し、最終的にはビジネスの複雑さに基づいて議論することができます。
planSummary
- COLLSCAN:フルテーブルスキャン
- IXSCAN { field_name: 1 }:インデックスクエリ 内部で使用されているインデックス
- IDHACK:プライマリキーインデックスクエリ 他のクエリプランをスキップし、主キーに基づいてより優れたクエリを提供します。クエリクエリに_id 値が含まれている場合に表示されます。
keysExamined
- このクエリに対して既存のインデックスが適切かどうかを判断するために使用されます。
- クエリごとにスキャンされたインデックスの数を示し、値が大きいほど CPU の負荷が大きいです。
問題のコードの特定#
周期的な問題#
04:05(5 分間の平均値、したがって 04:00 から、UTC+8=12:05)
- sync_transaction_data
- タスク A(4 時間ごと)(主に MySQL Membership の読み取りと Redis の api db への書き込み)
04:15(12:15)
- タスク B
07:05(15:05)
- sync_transaction_data(午後 3 時に 2 回目)
- タスク C(主に MySQL の読み取り専用ライブラリ)
11:05(19:05)
- sync_transaction_data(午後 7 時に 3 回目)
- タスク C
非周期的な問題#
- (04:15-04:30、11:05-11:15)時間に基づいて、おそらくsync_transaction_dataの後続の問題です
- ただし、profileを使用して確認することもできます
その他の可能性のある原因#
周期的および非周期的な問題を除外した場合、まだ解決していない場合は、引き続き調査します。
実践#
- フリーズ環境で Profile パフォーマンスモニタリングを有効にし、レベルを 1 に設定し、閾値を 200 に設定します
- Flower を使用して非同期タスクの実行状況を監視します
- AWS CloudWatch を使用して CPU 使用状況を監視します
- フリーズシェルに入り、sync_transaction_data.delay()を実行します
- MongoDB にアクセスして、Bill の profile コレクションに格納されている遅いクエリログを確認します
- 900 以上のこのタイプのログ [1] が見つかります。フルテーブルスキャンです。
- 3 つのフィールド transaction_time、channel、settlement_sign がありますが、後の 2 つは 5 つのカテゴリの列挙フィールドと 0 と 1 のブールフィールドのみです。区別度が低すぎます。最初の transaction_time フィールドのみが適しています。
- インデックスを追加すると、CPU 使用率が 99.9%から 3%に低下し、非同期タスクの時間が 900 秒から 19 秒に短縮されます。
メンテナンスと予防#
- フリーズ環境で Profile パフォーマンスモニタリングを有効にします
- 定期的に遅いクエリをチェックして処理します
{
"op":"query",
"ns":"bill.transaction",
"keysExamined":0,
"query":{
"find":"transaction",
"filter":{
"transaction_time":{
"$gte":{"$date":"2018-05-20T23:00:00.000+0000"},
"$lte":{"$date":"2018-05-21T22:59:59.999+0000"}},
"channel":"非再惠渠道",
"settlement_sign":{
"$in":[1]}}
},
"docsExamined":2882636,
"cursorExhausted":true,
"numYield":22635,
"nreturned":0,
"responseLength":104,
"protocol":"op_query",
"millis":15131,
"planSummary":"COLLSCAN",
"execStats":{
"stage":"COLLSCAN",
"nReturned":0,
"executionTimeMillisEstimate":14727,
"works":2882638,
"advanced":0,
"needTime":2882637,
"needYield":0,
"saveState":22635,
"restoreState":22635,
"isEOF":1,
"invalidates":0,
"direction":"forward",
"docsExamined":2882636
},
"ts":{
"$date":"2018-05-23T12:30:42.539+0000"
}
}