すべてのクエリを MongoDB に記録する

1. MongoDB の getLog コマンド
2. MongoDB でのログ クエリの詳細レベル
3. MongoDB で遅い操作をログに記録する
4. mongosh 内のログ クエリの結果をフィルター処理する
5. jq を使用して mongosh 外のログ クエリの結果をフィルター処理する

この記事では、MongoDB でのクエリのログ記録について学習します。 さらに、MongoDB でクエリをログに記録するために使用される演算子について詳しく説明します。

MongoDB の getLog コマンド

管理者コマンド getLog は、ログに記録された最新の 1024 件の mongod の発生を取得します。 getLog コマンドは、mongod ログ ファイルからログ データを取得しません。 代わりに、ログに記録された mongod イベントの RAM キャッシュから情報を取得します。

db.adminCommand() 関数を使用して getLog. を実行します。 getLog は、MongoDB 4.4 以降、ログ データをエスケープされた Relaxed Extended JSON v2.0 形式で配信します。 ログ データは、以前はプレーン テキストで配信されていました。

getLog コマンドの構文は次のとおりです。

db.adminCommand( { getLog: <value> } )

getLog の可能な値は次のとおりです。

* を指定すると、コマンドは他の有効な値の名前を含むドキュメントを返します。 それ以外の場合、コマンドは次のフィールドを持つドキュメントを生成します。

1. ログ イベントの数を含む totalLinesWritten フィールド。
2. ログ イベントの配列を含む log フィールド。
3. db.adminCommand() からのステータスとタイムスタンプ情報を提供する応答ドキュメント。

MongoDB での getLog コマンドの行切り捨て動作

MongoDB 4.2 以降、getLog は 1024 文字を超えるイベントを切り捨てます。 以前のバージョンでは、512 文字を超えると切り捨てられます。

MongoDB での getLog コマンドの文字回避動作

MongoDB 4.4 以降、getLog はログ データをエスケープされた Relaxed Extended JSON v2.0 形式で配信し、以下に示すエスケープ シーケンスを利用してログ出力を有効な JSON に変換します。

上記以外の制御文字は、uXXXX, でエスケープされます。ここで、XXXX は Unicode コードポイントの 16 進コードポイントです。 不適切な UTF-8 エンコーディングのバイトは、ufffd Unicode 置換文字に置き換えられます。

MongoDB でのログ クエリの詳細レベル

ログの詳細レベルを変更して、MongoDB によって生成されるログ メッセージの数を増減できます。 詳細度は、すべてのコンポーネントについてまとめて変更することも、コンポーネントを個別に特定することもできます。

詳細度の影響を受けるのは、重大度カテゴリ情報およびデバッグのログ エントリのみです。 これらのレベルを超えると、重大度カテゴリが常に表示されます。

詳細設定を高い値に設定して、デバッグ中または開発中に広範なログを記録するか、低い値に設定して、検証済みの本番環境へのログ書き込みを制限します。

MongoDB で現在のログの詳細レベルを調べる

db.getLogComponents() 関数を使用して、現在の冗長レベルを確認します。

db.getLogComponents()

出力は次のようになります。

最初のエントリ verbosity, は、すべてのコンポーネントのグローバルな詳細レベルです。 続いて accessControl, などの名前が付けられたコンポーネントは、そのコンポーネントの特定の詳細レベルを示し、設定されている場合はグローバル詳細レベルをオーバーライドします。

-1 の値は、(command のように) グローバル詳細レベルの 1つがなければ、コンポーネントが親の詳細レベルを継承することを示します。

MongoDB でログの詳細レベルを構成する

systemLog.verbosity および systemLog.component.name>.verbosity は logComponentVerbosity 引数を設定し、db.setLogLevel() 関数はすべて冗長性の量を変更するために使用できます。

systemLog 詳細設定を使用してレベルを制御する

systemLog.verbosity パラメータを使用して、すべてのコンポーネントのデフォルトのログ レベルを指定します。 systemLog.component.name>.verbosity 設定を使用して、特定のコンポーネントのレベルを制御します。

たとえば、以下の設定では、systemLog.verbosityを1、systemLog.component.query.verbosityを2、systemLog.component.storage.verbosityを2、そしてsystemLog.component.storage.journal.verbosityを1に設定します：

systemLog:
   verbosity: 1
   component:
      query:
         verbosity: 2
      storage:
         verbosity: 2
         journal:
            verbosity: 1

mongod または mongos インスタンスの場合、これらの設定を構成ファイルまたはコマンド ラインで指定します。

構成で明示的に指定されていないすべてのコンポーネントの詳細レベルは -1 です。 これは、それらがグローバル詳細レベルのいずれかを持っている場合、親の詳細レベルを取ることを示します。

logComponentVerbosity パラメータを変更する

詳細設定を含むドキュメントを渡して、logComponentVerbosity オプションを変更します。

たとえば、次のコマンドは、デフォルトの詳細レベルを 2 に、query を 3 に、storage を 4 に、storage.journal を 1 に変更します。

db.adminCommand( {
   setParameter: 1,
   logComponentVerbosity: {
      verbosity: 2,
      query: {
         verbosity: 3
      },
      storage: {
         verbosity: 4,
         journal: {
            verbosity: 1
         }
      }
   }
} )

これらの値は、mongosh. から設定できます。

db.setLogLevel() を使用して MongoDB のログ レベルを変更する

単一コンポーネントのログ レベルを変更するには、db.setLogLevel() 関数を使用します。 コンポーネントに対して 0 から 5 の詳細レベルを定義するか、-1 を指定して親の詳細レベルを継承することができます。

たとえば、systemLog.component.query.verbosity をその親の詳細度 (つまり、デフォルトの詳細度) に設定するには、次のようにします。

db.setLogLevel(-1, "query")

この値は、mongosh. から設定できます。

MongoDB で遅い操作をログに記録する

クライアント操作 (クエリなど) は、低速操作のしきい値よりも時間がかかる場合、またはログの詳細レベルが 1 以上に設定されている場合にログに記録されます。

MongoDB 4.2 以降の読み取り/書き込み操作の場合、プロファイラー エントリと診断ログ メッセージ (つまり、mongod/mongos ログ メッセージ) には次のものが含まれます。

1. queryHash は、同じクエリ形式での遅い検索を検出する機能です。
2. planCacheKey は、低速クエリのクエリ プラン キャッシュに関する追加情報を提供します。

MongoDB 5.0 以降、スロー オペレーションのログ メッセージに、クライアント IP アドレスを指定する remote 列が含まれるようになりました。

与えられた出力例には、遅い集計操作に関する情報が含まれています。

{"t":{"$date":"2020-05-20T20:10:08.731+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn281","msg":"Slow query","attr":{"type":"command","ns":"stocks.trades","appName":"MongoDB Shell","command":{"aggregate":"trades","pipeline":[{"$project":{"ticker":1.0,"price":2.0,"priceGTE110":{"$gte":["$price",111.0]},"_id":0.0}},{"$sort":{"price":-1.0}}],"allowDiskUse":true,"cursor":{},"lsid":{"id":{"$uuid":"fa658f9e-9cd6-42d4-b1c8-c9160fabf2a2"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1590005405,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"$db":"test"},"planSummary":"COLLSCAN","cursorid":1912190691485054730,"keysExamined":0,"docsExamined":1000001,"hasSortStage":true,"usedDisk":true,"numYields":1002,"nreturned":101,"reslen":17738,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":1119}},"Global":{"acquireCount":{"r":1119}},"Database":{"acquireCount":{"r":1119}},"Collection":{"acquireCount":{"r":1119}},"Mutex":{"acquireCount":{"r":117}}},"storage":{"data":{"bytesRead":232899899,"timeReadingMicros":186017},"timeWaitingMicros":{"cache":849}},"remote": "192.168.14.15:37666","protocol":"op_msg","durationMillis":22427}}

remoteOpWaitMillis フィールドでシャードの待機時間を取得する

MongoDB 5.0 以降では、remoteOpWaitMillis ログ フィールドを使用して、シャードからの結果の待機時間 (ミリ秒単位) を取得できます。

remoteOpWaitMillis については、次の値のみが報告されます。

1. 動作が遅い場合は、ロギングが有効になっています。
2. 結果を結合するシャードまたはmongos,

ログ内の durationMillis と remoteOpWaitMillis の時間列を比較して、マージ操作またはシャードの問題がクエリの低速化の原因であるかどうかを確認します。 durationMillis は、クエリが完了するまでにかかった全体の時間です。

具体的には、

1. durationMillis が remoteOpWaitMillis を超えた場合、ほとんどの時間がシャード応答の待機に費やされました。 たとえば、18 の durationMillis と 15 の remoteOpWaitMillis は許容値です。
2. durationMillis が remoteOpWaitMillis よりも大幅に大きい場合、ほとんどの時間がマージに費やされています。 たとえば、150 の durationMillis と 15 の remoteOpWaitMillis です。

mongosh 内のログ クエリの結果をフィルター処理する

getLog の出力をフィルタリングして、結果を読みやすくしたり、特定の基準に一致させたりすることができます。

次のコマンドは、各ログ メッセージから文字エスケープを削除しながら、log フィールド (現在のすべてのログ イベントの配列を含む) のみを出力します。

db.adminCommand( { getLog:'global'} ).log.forEach(x => {print(x)})

この操作では、getLog の出力が MongoDB ログ ファイル と同じ形式で表示されます。

注意: getLog は、ログに記録された最後の 1024 個の mongod イベントのみを表示し、MongoDB ログ ファイルを置き換えることを意図したものではありません。

jq を使用して mongosh 外のログ クエリの結果をフィルター処理する

サードパーティの jq コマンドライン プログラムは、MongoDB の構造化ログを扱うときに便利です。 ログエントリの迅速なプリティプリントと、堅牢なキーベースのマッチングとフィルタリングを可能にします。

jqは、Linux、Windows、および macOS 用の無料でオープンソースの JSON パーサーです。

getLog 出力で jq を利用するには、mongosh に -eval オプションを使用する必要があります。 次のアクションでは、jq を使用して REPL コンポーネントをフィルタリングし、レプリケーションに関連するログ メッセージのみが表示されるようにします。

mongosh --quiet --eval "db.adminCommand( { getLog:'global'} ).log.forEach(x => {print(x)})" | jq -c '. | select(.c=="REPL")'

-host や -port. など、必要な接続固有の引数を mongosh に与える場合は注意してください。

mongosh --quiet --eval "db.adminCommand( { getLog:'global'} ).log.forEach(x => {print(x)})" | jq -r ".msg" | sort | uniq -c | sort -rn | head -10

利用可能なログ フィルタを取得する

mongosh から実行される次の操作は、getLog に渡すために使用可能なログ フィルターを返します。

db.adminCommand( { getLog: "" } )

この操作は次のドキュメントを返します。

{ "names" : [ "global", "startupWarnings" ], "ok" : 1 }

ログから最近のイベントを取得する

mongosh から実行される次のコマンドは、mongod の最新の global イベントを取得します。

db.adminCommand( { getLog : "global" } )

この操作により、次のようなドキュメントが生成されます。