More than 5 years have passed since last update.

MongoDB v4 explain 結果をちゃんと理解してクエリ改善 (前半:explain結果の見方)

MongoDB

Last updated at 2019-04-30Posted at 2019-04-30

@koshi_life です。

MongoDBのクエリ高速化に興味があり、Explain Results を理解したく調べたことの備忘です。

前提

MongoDB v4.0.3
シャードなし
参考リンクは2019年4月末時点のものを参考にしています。

事前に確認したもの

mongoDB - Indexes

クエリ改善するに当たり、MongoDBのインデックス概要ページは必読。
とても読みやすい日本語訳もQiitaにありました。

テストデータ

Qiitaサービスインの2011年〜2019年4月のある断面までの全記事 396,416件をv2 APIで取得しました。以下が保存した 1docの中身です。

.js

{
    "_id": ObjectID("5cbb36d11fc6a6c823466a06"),
    "item_id": "634799bb57872ce0a169",
    "user_id": "koshilife",
    "title": "Node.js StreamAPI から逃げちゃダメだ。逃げちゃダメだ。。",
    "url": "https://qiita.com/koshilife/items/634799bb57872ce0a169",
    "likes_count": "131",
    "tags": [
        "Node.js",
        "StreamAPI"
    ],
    "created_at": ISODate("2015-06-22T00:46:48.000Z"),
    "month": "201506",
    "day": "20150622"
}

参考： Qiita記事取得は以下の過去エントリーで挙げたプログラムで取得しています。
Qiita API v2 で記事取得する (Ruby)

index状態

.js

mongo> db.qiita_items.getIndexes()
[
	{
		"v" : 2,
		"key" : {
			"_id" : 1
		},
		"name" : "_id_",
		"ns" : "qiita_api_development.qiita_items"
	}
]

対象のクエリ

ありがちな1ユーザの最新投稿３件を取得するクエリを改善対象とします。

.js

mongo> db.qiita_items.find({'user_id':'koshilife'},{'_id':0,'created_at':1,'title':1,'url':1}).sort({'created_at':-1}).limit(3)
{ "title" : "MongoDB Aggregation 100本ノック 前半 (group, sort, limit, project)", "url" : "https://qiita.com/koshilife/items/422070ee6aa636fb75fc", "created_at" : ISODate("2019-04-15T11:52:57Z") }
{ "title" : "Mongoid 特定Collectionにのみインデックスを作る", "url" : "https://qiita.com/koshilife/items/140b5a66d5fa6d1e7ee1", "created_at" : ISODate("2019-04-14T15:06:26Z") }
{ "title" : "Google Sheets API v4「1セル 50000文字までの制限あるよ」", "url" : "https://qiita.com/koshilife/items/5aff56c1bb9e5d31067f", "created_at" : ISODate("2019-04-08T01:31:04Z") }

explain 結果について

対象クエリの explain 結果を確認してみます。
対象クエリにexplain()をつけるだけで確認できます。
引数 executionStats はより詳細な内容を表示してくれるオプションです。

.js

mongo> db.qiita_items.find({'user_id':'koshilife'},{'_id':0,'created_at':1,'title':1,'url':1}).sort({'created_at':-1}).limit(3).explain('executionStats')
{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "qiita_api_development.qiita_items",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"user_id" : {
				"$eq" : "koshilife"
			}
		},
		"winningPlan" : {
			"stage" : "PROJECTION",
			"transformBy" : {
				"_id" : 0,
				"created_at" : 1,
				"title" : 1,
				"url" : 1
			},
			"inputStage" : {
				"stage" : "SORT",
				"sortPattern" : {
					"created_at" : -1
				},
				"limitAmount" : 3,
				"inputStage" : {
					"stage" : "SORT_KEY_GENERATOR",
					"inputStage" : {
						"stage" : "COLLSCAN",
						"filter" : {
							"user_id" : {
								"$eq" : "koshilife"
							}
						},
						"direction" : "forward"
					}
				}
			}
		},
		"rejectedPlans" : [ ]
	},
	"executionStats" : {
		"executionSuccess" : true,
		"nReturned" : 3,
		"executionTimeMillis" : 965,
		"totalKeysExamined" : 0,
		"totalDocsExamined" : 396416,
		"executionStages" : {
			"stage" : "PROJECTION",
			"nReturned" : 3,
			"executionTimeMillisEstimate" : 712,
			"works" : 396423,
			"advanced" : 3,
			"needTime" : 396419,
			"needYield" : 0,
			"saveState" : 3105,
			"restoreState" : 3105,
			"isEOF" : 1,
			"invalidates" : 0,
			"transformBy" : {
				"_id" : 0,
				"created_at" : 1,
				"title" : 1,
				"url" : 1
			},
			"inputStage" : {
				"stage" : "SORT",
				"nReturned" : 3,
				"executionTimeMillisEstimate" : 712,
				"works" : 396423,
				"advanced" : 3,
				"needTime" : 396419,
				"needYield" : 0,
				"saveState" : 3105,
				"restoreState" : 3105,
				"isEOF" : 1,
				"invalidates" : 0,
				"sortPattern" : {
					"created_at" : -1
				},
				"memUsage" : 1041,
				"memLimit" : 33554432,
				"limitAmount" : 3,
				"inputStage" : {
					"stage" : "SORT_KEY_GENERATOR",
					"nReturned" : 45,
					"executionTimeMillisEstimate" : 694,
					"works" : 396419,
					"advanced" : 45,
					"needTime" : 396373,
					"needYield" : 0,
					"saveState" : 3105,
					"restoreState" : 3105,
					"isEOF" : 1,
					"invalidates" : 0,
					"inputStage" : {
						"stage" : "COLLSCAN",
						"filter" : {
							"user_id" : {
								"$eq" : "koshilife"
							}
						},
						"nReturned" : 45,
						"executionTimeMillisEstimate" : 694,
						"works" : 396418,
						"advanced" : 45,
						"needTime" : 396372,
						"needYield" : 0,
						"saveState" : 3105,
						"restoreState" : 3105,
						"isEOF" : 1,
						"invalidates" : 0,
						"direction" : "forward",
						"docsExamined" : 396416
					}
				}
			}
		}
	},
	"serverInfo" : {
		"host" : "KenjinoMacBook-Air.local",
		"port" : 27017,
		"version" : "4.0.3",
		"gitVersion" : "7ea530946fa7880364d88c8d8b6026bbc9ffa48c"
	},
	"ok" : 1
}

最初はさっぱりでしたが、公式ページと以下エントリーが大変参考になりました。

explain結果の見方 (実行計画 queryPlanner)

queryPlanner のブロックでは実行計画の内容が確認できます。
queryPlanner の構造は以下です。

.js

"queryPlanner" : {
"plannerVersion" : ,
"namespace" : ,
"indexFilterSet" : ,
"parsedQuery" : {
...
},
"winningPlan" : {
"stage" : ,
...
"inputStage" : {
"stage" : ,
...
"inputStage" : {
...
}
}
},
"rejectedPlans" : [
,
...
]
}


インデックスが効いているかどうかを確認するには、query optimizerに選ばれた実行される計画の
`winningPlan`内の`winningPlan.stage` もしくは `winningPlan.inputStage.stage` に着目します。

Stages種別の一部。

|Stage種別|公式|意訳|
|:--|:--|:--|
|COLLSCAN|for a collection scan|コレクション内をフルスキャン|
|IXSCAN|for scanning index keys|インデックスを使ってスキャン|
|FETCH|for retrieving documents|検索|
|SHARD_MERGE|for merging results from shards|シャードの結果をマージ|
|SHARDING_FILTER|for filtering out orphan documents from shards|シャードの孤立したdocを除外|

もし`COLLSCAN` の記載があればコレクションのフルスキャンが発生しているので、
スロークエリの発生状況や、後述の実行計画(詳細版)を見てインデックス化を検討する等の改善アクションが見込まれます。


## 実行計画の詳細 executionStats

`explain('executionStats')`の引数指定で`winningPlan`の完全な実行計画の内容が確認できます。

以下、出力結果から抜粋です。

```.js
{
 "executionStats" : {
   "executionSuccess" : true,    // クエリ成功可否
   "nReturned" : 3,              // 返却したドキュメント数
   "executionTimeMillis" : 965,  // 実行時間 (ミリ秒)
   "totalKeysExamined" : 0,      // インデックス利用後 絞ったエントリー数
   "totalDocsExamined" : 396416, // 走査したドキュメント数
   "executionStages" : { ... }   // 各ステージごとの統計情報 (後述)
 }
}

39万ドキュメントをフルスキャンして、965msかかっていることがわかります。

executionStagesの内容には、stageの親子関係、クエリ内容、走査したドキュメント数、途中時点の返却数等の内容が確認できます。公式ドキュメントに載っている範囲で表示項目を意訳してコメントしています。

.js

	"executionStages": {
		"stage": "PROJECTION",
		"nReturned": 3,
		"executionTimeMillisEstimate": 712,
		"works": 396423,                    // stage実行によるwork unitsの数
		"advanced": 3,                      // 親ステージに返却された中間時点のstage返却数
		"needTime": 396419,                 // 親ステージに進むことができなかった中間結果の work cycles の数
		"needYield": 0,                     // stageが中断しロックを開放をストレージ層が要求した数
		"saveState": 3105,                  // stageが保存した処理を中断し保存した回数。例えばロック開放するための準備など。
		"restoreState": 3105,               // stageが保存した実行状態を保存したクエリ状態を復元した回数。例えば以前に開放したロックを回復した後など。
		"isEOF": 1,                         // stageがストリームの終わりに達したかどうか (true: 終わりに達した)
		"invalidates": 0,
		"transformBy": {
			"_id": 0,
			"created_at": 1,
			"title": 1,
			"url": 1
		},
		"inputStage": {
			"stage": "SORT",
			"nReturned": 3,
			"executionTimeMillisEstimate": 712,
			"works": 396423,
			"advanced": 3,
			"needTime": 396419,
			"needYield": 0,
			"saveState": 3105,
			"restoreState": 3105,
			"isEOF": 1,
			"invalidates": 0,
			"sortPattern": {
				"created_at": -1
			},
			"memUsage": 1041,
			"memLimit": 33554432,
			"limitAmount": 3,
			"inputStage": {
				"stage": "SORT_KEY_GENERATOR",
				"nReturned": 45,
				"executionTimeMillisEstimate": 694,
				"works": 396419,
				"advanced": 45,
				"needTime": 396373,
				"needYield": 0,
				"saveState": 3105,
				"restoreState": 3105,
				"isEOF": 1,
				"invalidates": 0,
				"inputStage": {
					"stage": "COLLSCAN",
					"filter": {
						"user_id": {
							"$eq": "koshilife"
						}
					},
					"nReturned": 45,
					"executionTimeMillisEstimate": 694,
					"works": 396418,
					"advanced": 45,
					"needTime": 396372,
					"needYield": 0,
					"saveState": 3105,
					"restoreState": 3105,
					"isEOF": 1,
					"invalidates": 0,
					"direction": "forward",
					"docsExamined": 396416  // stageが走査したドキュメント数
				}
			}
		}
	}

executionStages内容を読み解きstageの親子関係に注目して整理してみました。

StageNo	stage	stage内容	advanced	docsExamined	そのstageの executionTimeMillisEstimate
1	PROJECTION	射影(created_at/title/url)	3	-	0 (712-712)
2	SORT	created_at降順でソートして3件返却	3	-	18 (712-694)
3	SORT_KEY_GENERATOR	?	45	-	0 (694-694)
4	COLLSCAN	フルスキャンして user_id='koshilife'でフィルタ	45	396416	694

結果フルスキャンしている COLLSCAN の処理に全体の 97.4% (694/712) の時間が見込まれることがわかり、このフルスキャン処理に改善効果があることがわかりました。

改善は次回エントリーにて

長くなってしまったので、調査結果を元にした改善は次回エントリーにて。

(追記:2019/04/30) 続きを書きました

MongoDB v4 explain 結果をちゃんと理解してクエリ改善 (後半:クエリ改善)

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up