🍀

もしもISUCON10の予選問題がMongoDBのまま競技が開始してしまったら

2021/04/09に公開

MongoDB

ISUCON

tech

これなに

以前にISUCON10の予選問題をMongoDBに書き換えるという謎の素振りを行いました。

せっかく書き換えたのでこちらのスコアを上げていってMongoDBともっと仲良くなっていこうと思います。

ボトルネックを調べる

まずは初期段階のアプリケーションに対し alp でボトルネックとなっているエンドポイントを調べると

GET /api/estate/search
GET /api/chair/search

あたりがリクエスト量も処理時間も大きいということがわかりました。

処理内容からしてMongoDBが原因のように見えるので、MongoDBのスロークエリログを確認できるよう準備します。
MongoDBのスロークエリログを出力するためにはコンソールから

db.setProfilingLevel(1)

というコマンドを実行します。ちなみに 1 と指定しているとこは様々な設定ができて、

0 : 設定なし
1 : 設定以上の時間がかかったクエリをログに残す（デフォルトは100msecで変更可能）
2 : 全てのクエリをログに残す

となっています。

ここで1つ問題があって、このスロークエリロギングはデータベースごとに system.profile というコレクション（RDBでいうとこのテーブル）を新たに作って、そこにデータを保存していくような動作になっているのですが、POST /initialize ではベンチマーク用の初期データを作るためにデータベース自体を1回ドロップしているのですね。
このときに setProfilingLevel() の設定も一緒にドロップされてしまうので、スロークエリログをベンチごとに取りたければ POST /initialize 内で設定してあげる必要がありました。

ということで、開発中は POST /initialize に以下の1行を追加してあげます。

mongodb.RunCommand(context.Background(), bson.M{"profile": 1})

setProfilingLevel(1) の実態は runCommand({profile: 1}) のラッパーなので、上記のようになります。

これで無事にスロークエリログが確認できるようになりました。

前述したようにMongoDBのスロークエリログは system.profile というコレクションに保存されていくので、確認もMongoDBにクエリを実行するのと同じ要領です。
まずは一番時間がかかっているクエリTOP10を見ていきましょう。

> db.system.profile.find({}, {command:1, millis:1}).sort({millis: -1}).limit(10)
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(90) } }, { "door_height" : { "$gte" : NumberLong(177) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(90) } }, { "door_height" : { "$gte" : NumberLong(136) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(177) } }, { "door_height" : { "$gte" : NumberLong(90) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(177) } }, { "door_height" : { "$gte" : NumberLong(136) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(136) } }, { "door_height" : { "$gte" : NumberLong(90) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(136) } }, { "door_height" : { "$gte" : NumberLong(177) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("f0735c78-0fdc-4144-842a-7c718dd1a353") }, "$db" : "isuumo" }, "millis" : 481 }
{ "command" : { "find" : "estate", "filter" : { "" : null }, "limit" : NumberLong(20), "sort" : { "rent" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("17bbc12a-5590-4d21-bbbf-d8a102d2537e") }, "$db" : "isuumo" }, "millis" : 433 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(160) } }, { "door_height" : { "$gte" : NumberLong(193) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(160) } }, { "door_height" : { "$gte" : NumberLong(34) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(193) } }, { "door_height" : { "$gte" : NumberLong(160) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(193) } }, { "door_height" : { "$gte" : NumberLong(34) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(34) } }, { "door_height" : { "$gte" : NumberLong(160) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(34) } }, { "door_height" : { "$gte" : NumberLong(193) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("c271c5f1-af2d-4eea-b151-d9c0e334ca75") }, "$db" : "isuumo" }, "millis" : 399 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(181) } }, { "door_height" : { "$gte" : NumberLong(117) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(181) } }, { "door_height" : { "$gte" : NumberLong(76) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(117) } }, { "door_height" : { "$gte" : NumberLong(181) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(117) } }, { "door_height" : { "$gte" : NumberLong(76) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(76) } }, { "door_height" : { "$gte" : NumberLong(181) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(76) } }, { "door_height" : { "$gte" : NumberLong(117) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("718bfb3d-9305-494d-b28b-71ab65f8a4ee") }, "$db" : "isuumo" }, "millis" : 388 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(130) } }, { "door_height" : { "$gte" : NumberLong(58) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(130) } }, { "door_height" : { "$gte" : NumberLong(91) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(58) } }, { "door_height" : { "$gte" : NumberLong(130) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(58) } }, { "door_height" : { "$gte" : NumberLong(91) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(91) } }, { "door_height" : { "$gte" : NumberLong(130) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(91) } }, { "door_height" : { "$gte" : NumberLong(58) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("afd09016-2fb9-4bcb-a32a-e89c8b1e0da4") }, "$db" : "isuumo" }, "millis" : 371 }
{ "command" : { "find" : "estate", "filter" : { "" : null }, "limit" : NumberLong(20), "sort" : { "rent" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("8136b1d4-56a1-4fff-b8f8-2a1f5d3b2129") }, "$db" : "isuumo" }, "millis" : 360 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(105) } }, { "door_height" : { "$gte" : NumberLong(105) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(105) } }, { "door_height" : { "$gte" : NumberLong(164) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(105) } }, { "door_height" : { "$gte" : NumberLong(105) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(105) } }, { "door_height" : { "$gte" : NumberLong(164) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(164) } }, { "door_height" : { "$gte" : NumberLong(105) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(164) } }, { "door_height" : { "$gte" : NumberLong(105) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("718bfb3d-9305-494d-b28b-71ab65f8a4ee") }, "$db" : "isuumo" }, "millis" : 336 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(119) } }, { "door_height" : { "$gte" : NumberLong(158) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(119) } }, { "door_height" : { "$gte" : NumberLong(30) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(158) } }, { "door_height" : { "$gte" : NumberLong(119) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(158) } }, { "door_height" : { "$gte" : NumberLong(30) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(30) } }, { "door_height" : { "$gte" : NumberLong(119) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(30) } }, { "door_height" : { "$gte" : NumberLong(158) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("9573734e-4c1c-4571-87af-82380da7f091") }, "$db" : "isuumo" }, "millis" : 330 }
{ "command" : { "find" : "estate", "filter" : { "$or" : [ { "$and" : [ { "door_width" : { "$gte" : NumberLong(183) } }, { "door_height" : { "$gte" : NumberLong(176) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(183) } }, { "door_height" : { "$gte" : NumberLong(157) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(176) } }, { "door_height" : { "$gte" : NumberLong(183) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(176) } }, { "door_height" : { "$gte" : NumberLong(157) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(157) } }, { "door_height" : { "$gte" : NumberLong(183) } } ] }, { "$and" : [ { "door_width" : { "$gte" : NumberLong(157) } }, { "door_height" : { "$gte" : NumberLong(176) } } ] } ] }, "limit" : NumberLong(20), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("afd09016-2fb9-4bcb-a32a-e89c8b1e0da4") }, "$db" : "isuumo" }, "millis" : 330 }
{ "command" : { "find" : "estate", "filter" : { "" : null }, "limit" : NumberLong(20), "sort" : { "rent" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("c271c5f1-af2d-4eea-b151-d9c0e334ca75") }, "$db" : "isuumo" }, "millis" : 329 }

これらはどうやら GET /api/recommended_estate/:id や GET /api/estate/low_priced で呼ばれているクエリのようですね。この辺は追々改善しないといけないとして、今回直したいエンドポイントで呼ばれているクエリではないので、chair コレクションへのクエリに絞ってみます。

> db.system.profile.find({"ns" : "isuumo.chair"}, {command:1, millis:1}).sort({millis: -1}).limit(10)
{ "command" : { "aggregate" : "chair", "pipeline" : [ { "$match" : { "height" : { "$gte" : NumberLong(150) }, "stock" : { "$gt" : 0 } } }, { "$group" : { "_id" : 1, "n" : { "$sum" : 1 } } } ], "cursor" : {  }, "lsid" : { "id" : UUID("ba9ad5ac-25e8-4286-b52d-adbc84198150") }, "$db" : "isuumo" }, "millis" : 287 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("098e381f-fd41-4bca-9e5e-67f56785d6ad") }, "$db" : "isuumo" }, "millis" : 279 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("8136b1d4-56a1-4fff-b8f8-2a1f5d3b2129") }, "$db" : "isuumo" }, "millis" : 275 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("f23f1ae2-80e5-4110-b6a2-741adba2aacb") }, "$db" : "isuumo" }, "millis" : 275 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("9573734e-4c1c-4571-87af-82380da7f091") }, "$db" : "isuumo" }, "millis" : 266 }
{ "command" : { "find" : "chair", "filter" : { "height" : { "$gte" : NumberLong(150) }, "stock" : { "$gt" : 0 } }, "limit" : NumberLong(25), "skip" : NumberLong(50), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("6aa79ce6-7ca8-49e9-a424-65543fd5d61d") }, "$db" : "isuumo" }, "millis" : 265 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("17bbc12a-5590-4d21-bbbf-d8a102d2537e") }, "$db" : "isuumo" }, "millis" : 263 }
{ "command" : { "find" : "chair", "filter" : { "height" : { "$lt" : NumberLong(80) }, "stock" : { "$gt" : 0 } }, "limit" : NumberLong(25), "skip" : NumberLong(75), "sort" : { "popularity" : -1, "_id" : 1 }, "lsid" : { "id" : UUID("8136b1d4-56a1-4fff-b8f8-2a1f5d3b2129") }, "$db" : "isuumo" }, "millis" : 262 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("8136b1d4-56a1-4fff-b8f8-2a1f5d3b2129") }, "$db" : "isuumo" }, "millis" : 261 }
{ "command" : { "find" : "chair", "filter" : { "stock" : { "$gt" : 0 } }, "limit" : NumberLong(20), "sort" : { "price" : 1, "_id" : 1 }, "lsid" : { "id" : UUID("afd09016-2fb9-4bcb-a32a-e89c8b1e0da4") }, "$db" : "isuumo" }, "millis" : 251 }

1位をはじめ、上位にいくつか今回直したい対象である GET /api/chair/search で呼ばれているクエリがいますね。
1位におどり出た aggregate コマンドは直接的にはどこにも使っていませんが、検索結果の数を出すために使っている db.chair.countDocuments() が aggregate して $sum するオペレーションのラッパーであるためこのような結果となっています。

複雑なクエリに時間がかかっているというわけでもなさそう。むしろトータルの件数が多くなる単純なクエリのほうが時間がかかっているように見えるので、ソートに時間がかかっているのかもしれません。
MongoDBではインデックスを使わないソートをblocking sort operationと呼び、パフォーマンスの低下をはじめソート対象となるドキュメント全体のサイズ制限があるなど悪影響があります。

これでボトルネックらしき箇所を特定することができました。

クエリを改善してスコアを上げる

ボトルネックが特定できたら改善していきましょう。今回はインデックスを貼っていくのが良さそうです。まずは現状の動作を確認するために問題のクエリをexplain()します。MongoDBでもEXPLAINが存在し、これでクエリの実行計画を取れるのです。

> db.chair.find({height: {$gte: 150}, stock: {$gt: 0}}).sort({popularity: -1, _id : 1}).limit(25).skip(50).explain()
{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "isuumo.chair",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"stock" : {
						"$gt" : 0
					}
				},
				{
					"height" : {
						"$gte" : 150
					}
				}
			]
		},
		"queryHash" : "B7ABA21E",
		"planCacheKey" : "B7ABA21E",
		"winningPlan" : {
			"stage" : "SKIP",
			"skipAmount" : 50,
			"inputStage" : {
				"stage" : "SORT",
				"sortPattern" : {
					"popularity" : -1,
					"_id" : 1
				},
				"memLimit" : 104857600,
				"limitAmount" : 75,
				"type" : "simple",
				"inputStage" : {
					"stage" : "COLLSCAN",
					"filter" : {
						"$and" : [
							{
								"stock" : {
									"$gt" : 0
								}
							},
							{
								"height" : {
									"$gte" : 150
								}
							}
						]
					},
					"direction" : "forward"
				}
			}
		},
		"rejectedPlans" : [ ]
	},
	"serverInfo" : {
		"host" : "12edb33ac01a",
		"port" : 27017,
		"version" : "4.4.2",
		"gitVersion" : "15e73dc5738d2278b688f8929aee605fe4279b0e"
	},
	"ok" : 1
}

ウワァJSONで返ってくるのか、という気持ちになりますよね。私も同じ気持ちです。さておき、ここで注目してほしいのは winningPlan.inputStage.stage の SORT のところです。
インデックスを使わないソートことblocking sort operationが発生している場合このステージが出現します。

ではインデックスを貼ってblocking sort operationを防いでみます。今回は popularity が降順、_id が昇順の Compound Index を貼ります。

> db.chair.createIndex({popularity: -1, _id: 1})

1 を指定すると昇順、-1 を指定すると降順インデックスとなります。

これでさっきのクエリに explain() を実行すると...

> db.chair.find({height: {$gte: 150}, stock: {$gt: 0}}).sort({popularity: -1, _id : 1}).limit(25).skip(50).explain()
{
	"queryPlanner" : {
		"plannerVersion" : 1,
		"namespace" : "isuumo.chair",
		"indexFilterSet" : false,
		"parsedQuery" : {
			"$and" : [
				{
					"stock" : {
						"$gt" : 0
					}
				},
				{
					"height" : {
						"$gte" : 150
					}
				}
			]
		},
		"queryHash" : "B7ABA21E",
		"planCacheKey" : "B7ABA21E",
		"winningPlan" : {
			"stage" : "LIMIT",
			"limitAmount" : 25,
			"inputStage" : {
				"stage" : "SKIP",
				"skipAmount" : 50,
				"inputStage" : {
					"stage" : "FETCH",
					"filter" : {
						"$and" : [
							{
								"stock" : {
									"$gt" : 0
								}
							},
							{
								"height" : {
									"$gte" : 150
								}
							}
						]
					},
					"inputStage" : {
						"stage" : "IXSCAN",
						"keyPattern" : {
							"popularity" : -1,
							"_id" : 1
						},
						"indexName" : "popularity_-1__id_1",
						"isMultiKey" : false,
						"multiKeyPaths" : {
							"popularity" : [ ],
							"_id" : [ ]
						},
						"isUnique" : false,
						"isSparse" : false,
						"isPartial" : false,
						"indexVersion" : 2,
						"direction" : "forward",
						"indexBounds" : {
							"popularity" : [
								"[MaxKey, MinKey]"
							],
							"_id" : [
								"[MinKey, MaxKey]"
							]
						}
					}
				}
			}
		},
		"rejectedPlans" : [ ]
	},
	"serverInfo" : {
		"host" : "12edb33ac01a",
		"port" : 27017,
		"version" : "4.4.2",
		"gitVersion" : "15e73dc5738d2278b688f8929aee605fe4279b0e"
	},
	"ok" : 1
}

winningPlan.inputStage.stage から SORT がなくなっているのでインデックスが効いているようですね！
estate でも {popularity: -1, _id: 1} という同様のソートを行っているので、chairとestateの両方でこのインデックスを貼ってベンチを回してみましょう。
POST /initialize に以下のようなコードを追加するとインデックスを貼ることができます。

chairIndexModels := []mongo.IndexModel{
	{
		Keys: bson.D{{"popularity", -1}, {"_id", 1}},
	},
}
mongodb.Collection("chair").Indexes().CreateMany(context.Background(), chairIndexModels)

estateIndexModels := []mongo.IndexModel{
	{
		Keys: bson.D{{"popularity", -1}, {"_id", 1}},
	},
}
mongodb.Collection("estate").Indexes().CreateMany(context.Background(), estateIndexModels)

ベンチマークを回してみる

今回も初回のベンチと同じ環境である私のMacBook Proでベンチを回していきます。初回はMySQL版でおおよそ 530 くらい、MongoDB版でおおよそ 320 くらいとMySQLに敗北していたのですが今回はどうでしょうか！

{"pass":true,"score":496,"messages":[],"reason":"OK","language":"go"}

ということで 496 でした！MySQL版にはまだ負けてるけどちょっとスコアが改善されましたね！

おわりに

改善後のログを alp で解析すると、まだまだボトルネックは /search 関連のようです。また、平均の処理時間は /low_priced が /search よりも長くなっているのでこちらも要改善です。

自分で作った問題を自分で解いていくのは時折なんとも言えない虚無が訪れたような気持ちになったりもしますが、やってみると意外と結構楽しいのでもうしばらくこのアプリケーションを改善していこうと思います。

これなに

ボトルネックを調べる

クエリを改善してスコアを上げる

ベンチマークを回してみる

おわりに

Discussion