自己紹介
商品開発部の松葉と申します。
WEBエンジニアとして、「現場クラウドOne」というサービスの開発に携わっています。
今回は現場クラウドOneが抱えていた問題の調査、それに対する対策と改善結果についてご紹介します。
現場クラウドOneについて
現場クラウド One は、建設業の発注者と受注者のやりとりを円滑にする建設業専用のクラウドサービスです。前身サービスである「現場クラウド for サイボウズOffice」からのリニューアルという形で、昨年6月にリリースしました。
詳細についてはぜひ製品ページをご覧ください。
現場クラウド One | 受発注者間 工事情報共有システム（ASP）
システム的な話をすると、APPサーバー数台とDBサーバー1台で構成されており、いずれもAWS EC2で構築しています。データベースはDBサーバーにMongoDBをインストールして運用しています。
課題・目的
日々CloudWatchでサーバーの負荷状況を監視しているのですが、以前からDBサーバーのLoadAverageが瞬間的に上昇することがありました。
これまでは「何で跳ねてるんだろう？でも特にエラーも出てないしアプリケーションも止まってないから、まあいいや。」とスルーしてしまっていました。
しかし、現場クラウド One は主に公共工事でご利用いただいているサービスということもあり、例年年度末・年度始は工事終了や発注者の異動等に伴いアクセスが増加するため、それまでにスロークエリを洗い出して確実に潰しておき予期せぬ障害を未然に防ぎたいと思います。
調査
改めて、CloudWatchでDBサーバーのメトリクスを確認します。
↓は2023年2月6日のLoadAverageのグラフですが、瞬間的に上昇している時間があるのが分かります（14:35のプロットで最も上昇）
※00:00~明け方にかけては夜間のバッチ処理による上昇のため、今回は対策の対象外とする
このような山が、毎日1~3個ほどできていました。
次にMongoDBのログを確認してみます。
まず、短時間で頻出している・時間のかかっているクエリを洗い出すためにログを絞り込みます。
$ sudo grep "2023-02-06T14:3" <path_to>/mongod.log | grep "COLLSCAN" > stats.txt※mongodbのデフォルト設定では100ms以上かかったクエリしかログに残らない
次にawkで整形し内容を確認（printする項目は必要に応じて調整）
$ awk '{print $1,$6,$7,$8,$NF}' stats.txt | less
その結果、以下に示すorgs（組織）コレクションのクエリ（平均実行時間：140ms）が1秒間に100回近く実行されていることが確認できました。とても1秒間に収まる実行数ではないので、このクエリがLoadAverageの上昇に繋がったのではないかと推測できます。
db.orgs.find(
{
project_ids: { $elemMatch: { $in: [ ... ] } }
},
{ _id: true }
)
インデックス作成
まずは現状のインデックスを確認。
> db.orgs.getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_",
"ns" : "one.orgs"
}
]
project_idsフィールドのインデックス作成。
> db.orgs.creatIndex({"project_ids": 1})
作成後、再度インデックスを確認します。
> db.orgs.getIndexes()
[
{
"v" : 2,
"key" : {
"_id" : 1
},
"name" : "_id_",
"ns" : "one.orgs"
},
{
"v" : 2,
"key" : {
"project_ids" : 1
},
"name" : "project_ids_1",
"ns" : "one.orgs"
}
]
新たにインデックスが作成されているのが確認できました。
結果
インデックス作成によるパフォーマンスの変化を確認します。
インデックス作成前後の、DBサーバーのLoadAverageのグラフです。
インデックス作成後、瞬間的な上昇が目立たなくなったのと、明らかにベースラインが下がったことが分かります。
また、該当クエリのexplain結果がこちらです。
> db.orgs.find( { project_ids: { $elemMatch: { $in: [ ... ] } } }, { _id: true } ).explain( "executionStats" ).executionStats
{
"executionSuccess" : true,
"nReturned" : 0,
"executionTimeMillis" : 0,
"totalKeysExamined" : 6,
"totalDocsExamined" : 0,
"executionStages" : {
"stage" : "PROJECTION_SIMPLE",
...
"inputStage" : {
"stage" : "FETCH",
...
}
}
}
"executionTimeMillis" : 0とあるように、平均140msかかっていたクエリが1msに満たない時間で実行できるようになりました。
現在はほとんどグラフが跳ねることもなく、年度末・年度始を迎えてからも特に障害は発生していません。
まとめ
エラーとして表に出てくることのない問題を見つけ出す作業なので、初めはどこに目をつければ良いのかもわかりませんでしたが、なんとか要因を発見して対策を講じ、目に見える効果を得ることができました。
MongoDBのログの見方やコマンドの使い方など、自分にとって新しい学びがあったの同時に、今後はリリース後に慌てることがないよう、設計・開発段階でインデックスのチューニングやクエリの精査ができるよう心掛けていこうと思います。
