simon

simon

github

Mongo CPUオーバーロードの調査とログ

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 使用率が 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])。

Profiler パフォーマンス分析ログ#

  • Mongo クエリのパフォーマンスログ収集機能は、デフォルトでオフになっています。データベースのパフォーマンスにわずかな影響があるため、プリプロダクション環境でのみ有効にすることをお勧めします。
  • 主な機能は、データベースのコマンドと実行情報を、各 db の system フォルダの profile コレクションに保存することです。このコレクションのサイズは固定で、設定サイズを超えると古いログが自動的に削除されます。現在、最大で最新の 950 件のレコードを保存できます(大規模な遅いクエリのチェックに感謝します)。
  • プロファイラは、currentOp のログバージョンです。両者の返されるパラメータは完全に同じです。
  • プロファイラは、db.setProfilingLevel(level)を使用して設定できます。level には 3 つのレベルがあります:0(オフ)、1(操作の実行時間に基づいて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 にアクセスし、profile コレクションの bill 内の遅いクエリログを確認します
  • 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"
  }
}
読み込み中...
文章は、創作者によって署名され、ブロックチェーンに安全に保存されています。