読者です 読者をやめる 読者になる 読者になる

tweeeetyのぶろぐ的めも

アウトプットが少なかったダメな自分をアウトプット<br>\(^o^)/

mongodbのexplainを使って遅いクエリを調査してみてからのindex貼るメモ

はじめに

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万件って感じでだいぶ早くなりました。
めでたしめでたし。