はじめに

MongoDBのスロークエリ数を可視化するmackerelプラグインを作成した。

このプラグインを使うと以下のように1分間あたりのスロークエリ数をグラフ表示できる。

スロークエリの取得方法

そもそもMongoDBでスロークエリ数を取得するためにはどうすればいいのか。

MongoDBではDatabase Profilerを有効にすることで、CRUDオペレーションの情報を収集しsystem.profile コレクションに保持することができる。

プロファイラの設定値(公式ドキュメント)には以下のレベルがある。

レベル	レベル名	説明
0	off	プロファイラがオフの状態。何も収集しない。デフォルト値。
1	slowOp	実行時間がしきい値 `slowms` を超えたオペレーションだけ収集。
2	all	すべてのオペレーションを収集。

今回はスロークエリ数を監視したいので適当なしきい値と共にレベル1に設定する。

db.setProfilingLevel(1, { slowms: 50 })

設定ファイルで設定する場合(公式ドキュメント)は以下のようにする。

mongod.conf

operationProfiling:
   mode: slowOp
   slowOpThresholdMs: 50

この設定により50msを超えるオペレーションが system.profile コレクションに保存される。

スロークエリの詳細を知りたい場合は以下のクエリで取得する。

db.system.profile.find()

今回はmackerelプラグインでスロークエリ数を可視化することが目的なので、以下のようなクエリで直近1分のスロークエリ数をカウントする（実際にはMongoDBのGoドライバのmgo経由で取得する）。

db.system.profile.count({"ts" : { "$gt" : new Date(new Date() - 60 * 1000) } })

【注意】system.profileはCapped Collectionである

system.profileはデフォルトサイズが1MBのCapped Collectionである。コレクションサイズが1MBを超えると古いドキュメントが自動的に削除される。公式ドキュメントによると通常、数千件分のオペレーション情報を保持できるとのことだが筆者の環境では1,000件程度だった（1オペレーションのデータ長に依存するため）。

つまり、今回作成したプラグインでは直近1分間のクエリ数をカウントするが、1分以内に1MB分（数百〜数千件）のスロークエリが発生するような状況だと正しく数値を取ることができない、ということ。

これの解決策としては以下が考えられるので状況とお好みでどうぞ。

しきい値を引き上げ、スロークエリの発生件数を抑える
system.profileのサイズを変更する(公式ドキュメント)
- 手順が異様に複雑（特にsecondaryも対象にする場合）
- デカくしすぎるとsystem.profileへのクエリが重くなることも留意
sampleRateオプションでプロファイル対象とするオペレーションの割合を絞る
- MongoDB 3.6以降必須
- その分、スロークエリ数が少なく見える

余談ですが system.profileのサイズを設定ファイルで変更できるようにするチケットが既に切られているので誰か実装してくれないかなー

mackerelプラグインを作る

スロークエリ数の取得方法が分かったのであとはmackerelプラグインを書くだけ。

以下のドキュメントに従っていれば自然にmackerelプラグインの仕様を満たす。

https://mackerel.io/ja/docs/entry/advanced/go-mackerel-plugin
https://mackerel.io/ja/docs/entry/advanced/make-plugin-corresponding-to-installer

Goをほとんど書いたことがなかったのとghrを使ったことがなかったので以下の点でハマった。

Goプロジェクトを$GOPATH/src以下に配置しないとgoxzが動かない
ghrの以下のエラーで小一時間ハマっていたがGithub Tokenのパーミッションが不十分なだけだった

Failed to create GitHub release page: failed to create a release: POST https://api.github.com/repos/rinmu/mackerel-plugin-mongodb-slow-queries/releases: 404 Not Found []

コードの解説

全体的にはgo-mackerel-pluginのインタフェースに沿っているだけなので、ここではスロークエリ数の取得部分のみ解説する。

session, err := mgo.Dial(m.URL)
if err != nil {
	return nil, err
}

session.SetMode(mgo.Nearest, true)

collection := session.DB(m.Database).C("system.profile")
one_minute_ago := time.Now().Add(time.Duration(-1) * time.Minute)

count, err := collection.Find(bson.M{"ts": bson.M{"$gt": one_minute_ago}}).Count()
if err != nil {
	return nil, err
}

セッション取得

session, err := mgo.Dial(m.URL)

サードパーティ製のMongoDBドライバmgoを使う。
公式のmongo-go-driverを使いたいけどまだベータ版ぽいので保留。

read preferenceを指定

session.SetMode(mgo.Nearest, true)

レプリカセットでの運用を想定してread preferenceを指定している。
Nearestを指定するとprimary/secondaryに関係なく最も近い（ネットワークレイテンシの低い）メンバーから取得する。

【補足】 system.profileについて

system.prifileはレプリカセットの各メンバーが個別に保有するコレクションであり、レプリケーションされない。system.profileはそのメンバーに対して実行されたオペレーション情報を保持するのでこれは当然である。

Nearestを指定することにより、各メンバー（サーバー）上でpluginを実行することで、そのメンバーに対して発行されたスロークエリ数を取得できる。

スロークエリ数を取得

collection := session.DB(m.Database).C("system.profile")
one_minute_ago := time.Now().Add(time.Duration(-1) * time.Minute)

count, err := collection.Find(bson.M{"ts": bson.M{"$gt": one_minute_ago}}).Count()

前述のクエリと同じ。

使い方

プロファイラの設定を確認。無効になっている場合は有効にする。

> db.getProfilingStatus()
{ "was" : 0, "slowms" : 100, "sampleRate" : 1 }
> db.setProfilingLevel(1, {slowms: 50})
{ "was" : 0, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }
> db.getProfilingStatus()
{ "was" : 1, "slowms" : 50, "sampleRate" : 1 }

mkrがなければインストールしておく(公式ドキュメント)

mkrでmackrel-plugin-mongodb-slow-queriesをインストールする

sudo mkr plugin install rinmu/mackerel-plugin-mongodb-slow-queries

設定ファイルに追記

[plugin.metrics.mongodb-slow-queries]
command = "/path/to/mackerel-plugin-mongodb-slow-queries -database=your_database_name"

mackerel-agentをリロード

sudo /etc/init.d/mackerel-agent reload

所感

Goでの開発が初めてだったためハマりどころはあったが、mackerelの公式ページとヘルパーライブラリが充実しているのでプラグイン開発〜公開のハードルは低いと感じた。
スロークエリ数の他に、全クエリの平均実行時間も可視化したかった。が、MongoDBのDatabase Profilerの仕様上、レベルを2にして平均値を取ることになるため、スロークエリのみ取得のレベル1と両立できない。しきい値をプラグイン側に持たせてクエリで絞ることで両立は可能だが、system.profileのサイズ上限とクエリの実行時間に懸念があったのでひとまず断念した。