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

18 min read読了の目安(約17000字

これなに

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

https://zenn.dev/morihirok/articles/57d9b0295ac727

https://twitter.com/uskey512/status/1377840188018225153?s=20

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

ボトルネックを調べる

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

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

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

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

db.setProfilingLevel(1)

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

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

となっています。

https://docs.mongodb.com/manual/tutorial/manage-the-database-profiler

ここで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}) のラッパーなので、上記のようになります。

https://docs.mongodb.com/manual/reference/command/profile/

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

前述したように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/:idGET /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 するオペレーションのラッパーであるためこのような結果となっています。

https://docs.mongodb.com/manual/reference/method/db.collection.countDocuments/

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

https://docs.mongodb.com/manual/tutorial/sort-results-with-indexes/

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

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

ボトルネックが特定できたら改善していきましょう。今回はインデックスを貼っていくのが良さそうです。まずは現状の動作を確認するために問題のクエリを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.stageSORT のところです。
インデックスを使わないソートこと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} という同様のソートを行っているので、chairestateの両方でこのインデックスを貼ってベンチを回してみましょう。
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)

https://github.com/morihirok/isucon10-qualify/commit/00aa7c67a6b4fc2c46c3e84176c084185967ab80

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

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

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

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

おわりに

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

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

https://github.com/morihirok/isucon10-qualify