MongoDB cursor id not found (43) の原因と対策と調査過程から得た教訓

@koshi_life です。

MongoDB内に保存した大量のデータを加工する処理を行った際に、カーソルIDが見つからないMongoDB cursor id XXX not found (43) というエラーが度々発生し、原因と対策を調べた内容の備忘です。

前提

• MongoDB: v4.0.3
• mongoid: v7.0.2

TL;DR

cursor id not found (43) の原因と対策２つ。

• エラー原因１：タイムアウトの設定時間を超過した時 (デフォルト 10分)
  • 対策： cursor.noCursorTimeout() のオプションを設定する
• エラー原因２：バッチ取得サイズ16MBを超えた時 (デフォルト 16MB)
  • 対策- バッチ取得サイズを cursor.batchSize() で小さくする
• その他対策：Cursorを使わずに cursor.toArray() でRAM(メモリ) に全展開する

Ruby(Mongoid) の対策例

• 原因１の対策：noCursorTimeout設定をしてタイムアウトさせない

.rb

Model.no_timeout.all.each {|item| "処理内容" }

• 原因２の対策：16MB以下で取得できるよう1度に取得するバッチレコード数(バッチサイズ)を小さくする

.rb

Model.batch_size(10).all.each {|item| "処理内容" }

• その他対策：Curor使わず、メモリに全部展開させる(

.rb

Model.all.to_a.each {|item| "処理内容" }
Model.all.pluck(:field1, :field2).each {|item| "処理内容" } # pluckでメモリ展開領域の最小に留めるとなおよし

• 番外編：Cursorでできるだけ頑張りたいあなた(メモリを極力使いたくない時)
  長時間処理が止まらずに続けるため対策１と対策２と同じレコードを返さなくするCursor Snapshot hint() の合わせ技

.rb

Model.no_timeout.batch_size(1).hint('$natural':1).all.each {|item| "処理内容" }

※batch_size=1なのでネットワークIOコストがとても高いです。

参考

• Iterate a Cursor in the mongo Shell 公式Doc
• MongoDB - Error: getMore command failed: Cursor not found StackOverFlowの良回答
• MongoDBのcursor - demouth::blog 公式Docの図解付きの解説。とてもわかりやすい日本語エントリー

エラー内容

• railsコンソールの出力

.txt

Mongo::Error::OperationFailure (cursor id 289833215401 not found (43))

• mongoidのログ (対象コレクション名: sandbox.qiita_items)
  getMore にて発生していることがわかる。

.txt

MONGODB | localhost:27017 | sandbox.getMore | STARTED | {"getMore"=>289833215401, "collection"=>"qiita_items", "lsid"=>{"id"=><BSON::Binary:0x70363348449880 type=uuid data=0xb2bd0637a5234b85...>}}
MONGODB | localhost:27017 | sandbox.getMore | FAILED | cursor id 289833215401 not found (43) | 0.00041s

• エラー発生箇所 (Ruby)
  Qiita APIで取得した39万超の記事をQiitaItem.all でループさせてデータ処理していたら5万件くらいのところで毎度発生。

.rb

QiitaItem.all.each_with_index {|item, i| #"★★★この行でエラー★★★"
  "処理内容"
}

そもそも Cursor(カーソル) とは

エラー内容以前に、Cursorの理解が乏しく、いくつものStackOverFlowを経て、参考に挙げた日本語エントリー、公式ページを経て熟読し理解が深まった。

Cursorとはdb.collection.find()が返すオブジェクトであり、クエリ結果の読み込み位置を管理する役割を担う。

Cursorはiterate型なのでfor文等で全要素をループで取得することができるが、内部的な振る舞いとして、クエリ結果を1件づつMongoサーバから都度取得しているわけではなく、ある程度まとめて内部的に保持し、次の要素が無くなったら、getMoreにて次の要素郡を取得する振る舞いをしているとのこと。

詳細は、参考に挙げた公式Docと図解付きの日本語エントリーを読むとよいだろう。
上記エラーの発生箇所はこの getMore で発生していることがログからわかる。

Cursor仕様 (公式Docより)

Closure of Inactive Cursors
By default, the server will automatically close the cursor after 10 minutes of inactivity, or if client has exhausted the cursor. To override this behavior in the mongo shell, you can use the cursor.noCursorTimeout() method:

(意訳)カーソルは10分でクローズされるようになっているんだ。対策するならnoCursorTimeout()設定を使ってくれよな。

Cursor Batches
The MongoDB server returns the query results in batches. The amount of data in the batch will not exceed the maximum BSON document size. To override the default size of the batch, see batchSize() and limit().

(意訳)カーソルは必要になった際にまとめてサーバにクエリ結果をバッチ取得するけど、１バッチあたり最大値 16MB¹ を超えて取得することはできないんだ。対策するなら、batchSize(), limit()で取得するドキュメント数を指定してくれよな。

Cursor Isolation
As a cursor returns documents, other operations may interleave with the query. For the MMAPv1 storage engine, intervening write operations on a document may result in a cursor that returns a document more than once if that document has changed. To handle this situation, see the information on Cursor Snapshot.

(意訳)MMAPv1エンジンでは、カーソル返却後に他のクエリ操作で別ドキュメントが間に差し込まれた場合、同じドキュメントを返却することがあるんだ。対策するなら、Cursor Snapshot機能 を使ってくれよな。

Iterator Index より
The toArray() method loads into RAM all documents returned by the cursor; the toArray() method exhausts the cursor.

(意訳) ToArray()メソッドはカーソルの最後まで全てのドキュメントをRAMに展開してくれるぜ。

(あとがき)真実っぽい仕様にたどり着くまで

最初このIssueからTimeoutを疑い、試行錯誤したが、当てが外れて数時間の時間を浪費してしまった。

明らかにgetMoreのリクエストから10分もかからずエラーが発生していたので、こちらの線ではないことを早々に切り分けできなかったのが悔やまれる。

長時間のネットサーフィンといくつもの実験を経て、最終的に公式ページにたどり着き、問題解決に至った。

教訓：「急がば公式読め」

急がば回れじゃないが、公式Docをちゃんと読み込むのが一番早いこと。ありがち。

1. The maximum BSON document size is 16 megabytes. ↩