はじめに
mongodb×phpでいろいろ集計しているのですがphpにtimeoutでexception吐かれちゃいました的なときの
簡単な調査と対応メモに合わせてindexを貼るのもメモっておきます。
吐かれたエラーはこんな感じ
Fatal error: Uncaught exception \'MongoCursorTimeoutException\' with message \'10.2.xx.xx:27017: Read timed out after reading 0 bytes, waited for 30.000000 seconds\' in ・・・省略
まずはexplainの簡単な説明から
クエリの調査ってことで鉄板のexplainですがこんな感じで使います
db.collection.find().explain()
出力される結果はjson形式ですが各keyの意味はこんな感じ
| key | 説明 |
| cursor | カーソルタイプ。BasicCursor、BtreeCursor、GeoSearchCursorとか |
| isMultiKey | マルチキーインデックスを使っているか |
| n | 最終的にヒットしたドキュメント件数 |
| nscannedObjects | スキャンされたオブジェクトの数 |
| nscanned | スキャンされたオブジェクトorインデックスの数 |
| nscannedObjectsAllPlans | すべてのクエリでスキャンされたオブジェクトの総数 |
| nscannedAllPlans | すべてのクエリでスキャンされたオブジェクトorインデックスの数 |
| scanAndOrder | インデックスを使わずに結果をソートして返すか |
| indexOnly | クエリがインデックスのみを使っているか |
| nYields | 待っている書き込み処理を実行させるためにリードロックを解放した回数 |
| nChunkSkips | Chunkマイグレーション中にスキップしたドキュメント数 |
| millis | クエリを実行時間(ミリ秒) |
| indexBounds | インデックスを使って走査された要素の値の範囲(範囲検索なら上限と下限) |
※一部こちらを参考にさせていだきました
とりあえずのポイントとしてはこんな感じでしょうか
・millisが多いと当然遅い
・cursorがBasicCursorだとインデックスが使えていない
・nscannedがnよりも圧倒的に多いとindexが効いてないかも
→最終的な結果nを得るためにスキャンした対象が多い
というのを踏まえたうえでやってみた流れ
1.該当のクエリをexplainしてみる 2.indexに当たりをつけてindex貼ってみる 3.運用中のDBへのindex付与なのでついでにどんな感じになるか監視してみる 4.index貼り終わった後にexplain
1.該当のクエリをexplainしてみる
mongoシェルからexplain
>db.test.find({ "info.detail":1, "info.timestamp" : /2014-03-11/ }).explain()
{
"cursor" : "BtreeCursor info.timestamp_1 multi",
"isMultiKey" : false,
"n" : 115546,
"nscannedObjects" : 115546,
"nscanned" : 8246798,
"nscannedObjectsAllPlans" : 115546,
"nscannedAllPlans" : 8246798,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 18,
"nChunkSkips" : 0,
"millis" : 32970,
"indexBounds" : {
"info.timestamp" : [
[
"",
{
}
],
[
/2014-03-11/,
/2014-03-11/
]
},
"server" : "hoge.com:27017"
}
クエリの結果は30秒オーバー。
結果(n)100万件に対して、スキャンしたドキュメント(nscanned)が800万件です。
結果件数も多いですが、スキャンしたドキュメント数がはるかに多いのでindexを貼ってみます
2.indexに当たりをつけてindex貼ってみる
indexの貼り方
貼り方はいたって簡単でこんな感じ
db.collection.ensureIndex({"インデックス貼るkey":true})
とか
db.collection.ensureIndex({"インデックス貼るkey":true},{background:true} )
バックグラウンドオプションをつけることにより、バックグラウンドモードでのindex作成になります
バックグラウンドモードの特徴はこんな感じ
- インデックス作成中でも書き込みを含む他の操作が影響を受けない
- インデックスが作成完了するまでクエリーでそのインデックスは使わない
- インデックスの作成時間はオプション無しより長くなる
- 作成中はdb.currentOp() で実行中かどうか確認できる
ついでにindex
indexの確認はこんな幹事
db.collection.getIndexes()
貼ってみる
>db.test.ensureIndex({ "info.detail" : true, "info.timestamp":true }, {background:true} );
>※特に結果は出力されない
>※mongoのログには出てるのでそちらで確認してたりとか
index作成中のログを見てみる
# less /usr/local/mongodb/logs/mongodb.log
Mon Mar 11 19:13:42.275 [conn121026] build index hogedb.test { info.detail: 1.0, info.timestamp: 1.0 } background
Mon Mar 11 19:13:45.044 [conn121026] Background Index Build Progress: 111400/8493537 1%
Mon Mar 11 19:13:48.221 [conn121026] Background Index Build Progress: 265600/8493537 3%
Mon Mar 11 19:13:48.222 [conn120444] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 locks(micros) r:41 reslen:3333 104ms
Mon Mar 11 19:13:51.001 [conn121026] Background Index Build Progress: 383600/8493537 4%
Mon Mar 11 19:13:51.466 [conn121027] authenticate db: local { authenticate: 1, nonce: "a0637c0e35ae4e06", user: "__system", key: "a3e9e0a4f5dfb56543cfe804cba9b572" }
Mon Mar 11 19:13:52.692 [conn40] insert hogedb.test2 ninserted:2 keyUpdates:0 locks(micros) w:756861 378ms
Mon Mar 11 19:13:52.693 [conn120444] command admin.$cmd command: { serverStatus: 1 } ntoreturn:1 keyUpdates:0 locks(micros) r:42 reslen:3333 426ms
Mon Mar 11 19:13:54.005 [conn121026] Background Index Build Progress: 470600/8493537 5%
Mon Mar 10 19:13:57.000 [conn121026] Background Index Build Progress: 608100/8493537 7%
Mon Mar 10 19:14:00.000 [conn121026] Background Index Build Progress: 740400/8493537 8%
Mon Mar 10 19:14:03.000 [conn121026] Background Index Build Progress: 879900/8493537 10%
Mon Mar 10 19:14:06.042 [conn121026] Background Index Build Progress: 1013100/8493537 11%
Mon Mar 10 19:14:09.000 [conn121026] Background Index Build Progress: 1147600/8493537 13%ってな感じで「Background Index Build Progress」が数%ずつ進んでるのがわかります。
また、進んでる間に他のクエリも受け付けてくれてます。
3.運用中のDBへのindex付与なのでついでにどんな感じになるか監視してみる
おまけ的な感じですが、index作成中にどんな感じかuptimeとvmstatだけですが見てみました
uptime
- 通常時
18:36:48 up 85 days, 28 min, 11 users, load average: 0.14, 0.06, 0.01 18:36:54 up 85 days, 28 min, 11 users, load average: 0.20, 0.07, 0.02 18:37:00 up 85 days, 28 min, 11 users, load average: 0.18, 0.07, 0.02 18:37:04 up 85 days, 28 min, 11 users, load average: 0.17, 0.07, 0.02
- index作成中
19:17:40 up 84 days, 1:09, 11 users, load average: 3.28, 1.71, 1.15 19:17:45 up 84 days, 1:09, 11 users, load average: 3.02, 1.68, 1.14 19:17:48 up 84 days, 1:09, 11 users, load average: 2.78, 1.65, 1.14 19:17:52 up 84 days, 1:09, 11 users, load average: 2.78, 1.65, 1.14
loadがだいぶあがってます。cpuが結構がんばってる感じですね
vmstat -n 1 5
- 通常時
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 2 0 131976 1885548 217056 8150172 0 0 36 30 0 0 0 0 99 0 0 1 0 131976 1885036 217056 8150236 0 0 128 64 842 881 0 0 99 0 0 0 0 131976 1885532 217056 8150384 0 0 0 0 691 790 0 0 100 0 0 0 0 131976 1885160 217056 8150400 0 0 0 0 697 784 0 0 100 0 0 0 1 131976 1884260 217060 8150420 0 0 0 308 891 866 0 0 98 1 0
- index作成中
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 1 0 122212 148920 44008 10131056 0 0 35 29 0 0 0 0 99 0 0 2 0 122212 165652 44004 10115472 0 0 38072 1744 10865 1655 8 1 91 1 0 0 1 122212 168380 43940 10112120 0 0 32412 1668 7694 1649 9 1 87 3 0 0 1 122212 154236 43268 10125612 0 0 36792 1744 5383 1755 7 1 92 1 0 1 0 122212 162668 43276 10118728 0 0 37348 1496 9089 1756 7 1 92 1 0
ioとsystemな感じから割り込みやブロッキングが多発してそうです
って感じでおまけ程度でしたが、index作成中は結構なパワーを使いそうです
4.index貼り終わった後にexplain
ってことでindex作成し終わった後に再度explainしてみます
>db.test.find({ "info.detail":1, "info.timestamp" : /2014-03-11/ }).explain()
{
"cursor" : "BtreeCursor info.detail_1_info.timestamp_1 multi",
"isMultiKey" : false,
"n" : 115546,
"nscannedObjects" : 115546,
"nscanned" : 2251296,
"nscannedObjectsAllPlans" : 115546,
"nscannedAllPlans" : 2251296,
"scanAndOrder" : false,
"indexOnly" : false,
"nYields" : 17,
"nChunkSkips" : 0,
"millis" : 5804,
"indexBounds" : {
"info.detail" : [
[
1,
1
]
],
"info.timestamp" : [
[
"",
{
}
],
[
/2014-03-11/,
/2014-03-11/
]
]
},
"server" : "hoge.com:27017"
}クエリの結果は5秒程度。
結果(n)100万件に対して、スキャンしたドキュメント(nscanned)が200万件って感じでだいぶ早くなりました。
めでたしめでたし。
