StackOverflow2013

Note that there are some explanatory texts on larger screens.

plurals

POExtremely slow MongoCursor::next() performance
primarykey
Id
18018669
data
AcceptedAnswerId
0
AnswerCount
1
ClosedDate
CommentCount
1
CommunityOwnedDate
CreationDate
2013-08-02T13:54:50.957
FavoriteCount
0
LastActivityDate
2013-08-05T12:18:56.980
LastEditDate
2013-08-05T12:18:56.980
LastEditorUserId
965106
OwnerUserId
965106
ParentId
0
PostTypeId
1
Score
1
ViewCount
805
LastEditorDisplayName
text
Body
I was faced with an extremely slow <code>MongoCursor</code> performance under some conditions. <pre class="lang-php prettyprint-override"><code>$mongoClient = new MongoClient('mongodb://127.0.0.1:27017'); $collection = $mc->mydb->mycollection; </code></pre> <h3>test1:</h3> <pre class="lang-php prettyprint-override"><code>for($i=0; $i<1000; $i++) { $cursor = $collection->find()->limit(2); $cursor->next(); } </code></pre> Elapsed time: 41.78210 sec [24 ops/s] <h3>test2:</h3> <pre class="lang-php prettyprint-override"><code>for($i=0; $i<1000; $i++) { $cursor = $collection->find()->limit(1); $cursor->next(); } </code></pre> Elapsed time: 0.47898 sec [2 088 ops/s] <h3>test3:</h3> <pre class="lang-php prettyprint-override"><code>for($i=0; $i<1000; $i++) { $cursor = $collection->find()->limit(2)->batchSize(-2); $cursor->next(); } </code></pre> Elapsed time: 0.65439 sec [1 528 op/s] In test1 no matter whether <code>limit(2)</code> or <code>limit(200)</code> script does 24 ops/s always; I tested it with: <ul> <li>mongo v2.4.5</li> <li>php driver 1.4.0dev and 1.5.0dev</li> <li>Debian 6.0.7 and Ubuntu 12.10</li> </ul> Is this some issue in php driver? <h2>EDIT1:</h2> I did some logging via MongoLog and got interesting results: <pre><code>MongoLog::setLevel(MongoLog::ALL); MongoLog::setModule(MongoLog::IO); </code></pre> test1: (limit(N) where N > 1) <ul> <li>1375693731.5349 - IO (FINE): getting reply</li> <li>1375693731.5350 - IO (FINE): getting cursor header</li> <li>1375693731.5351 - IO (FINE): getting cursor body</li> <li>1375693731.5351 - IO (WARN): Killing unfinished cursor 63182808988603511</li> <li>1375693731.5352 - IO (FINE): getting reply</li> <li>1375693731.5353 - IO (FINE): getting cursor header</li> <li>1375693731.5726 - IO (FINE): getting cursor body</li> <li>1375693731.5727 - IO (WARN): Killing unfinished cursor 63182981334616260</li> <li>...</li> </ul> test2: (limit(1), limit(0) and without limit ) <ul> <li>1375693866.2663 - IO (FINE): getting reply</li> <li>1375693866.2663 - IO (FINE): getting cursor header</li> <li>1375693866.2663 - IO (FINE): getting cursor body</li> <li>1375693866.2665 - IO (FINE): getting reply</li> <li>1375693866.2665 - IO (FINE): getting cursor header</li> <li>1375693866.2665 - IO (FINE): getting cursor body</li> <li>...</li> </ul> as you can see when I limit query with N (where N>1) driver does <code>killing unfinished cursor</code> and next time when it tries to get cursor body it spends to much time. <h2>EDIT2:</h2> Yes, that timings concern collection with 20 documents only, but 20K documents will affect only limit(0) and noLimit, they will do kill cursor as you said. Here is the log with logLevel:5. I don't any clues. mongodb.log: limit(N) <ul> <li>Mon Aug 5 14:43:55.292 [conn3] query mydb.mycollection cursorid:1002459676459826 ntoreturn:2 ntoskip:0 nscanned:3 keyUpdates:0 locks(micros) r:84 nreturned:2 reslen:86 0ms</li> <li>Mon Aug 5 14:43:55.293 [conn3] killcursors: found 1 of 1</li> <li>Mon Aug 5 14:43:55.293 [conn3] killcursors keyUpdates:0 0ms</li> <li>Mon Aug 5 14:43:55.332 [conn3] runQuery called mydb.mycollection {}</li> <li>Mon Aug 5 14:43:55.333 [conn3] query mydb.mycollection cursorid:1002631131988423 ntoreturn:2 ntoskip:0 nscanned:3 keyUpdates:0 locks(micros) r:84 nreturned:2 reslen:86 0ms</li> </ul> mongodb.log: limit(1) <ul> <li>Mon Aug 5 14:45:54.899 [conn3] runQuery called mydb.mycollection {}</li> <li>Mon Aug 5 14:45:54.899 [conn3] query mydb.mycollection ntoreturn:1 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:39 nreturned:1 reslen:53 0ms</li> <li>Mon Aug 5 14:45:54.899 [conn3] runQuery called mydb.mycollection {}</li> <li>Mon Aug 5 14:45:54.899 [conn3] query mydb.mycollection ntoreturn:1 ntoskip:0 nscanned:1 keyUpdates:0 locks(micros) r:35 nreturned:1 reslen:53 0ms</li> </ul>
Tags
<php><performance><mongodb>
Title
Extremely slow MongoCursor::next() performance
singulars
PostAcceptedAnswerId
1. This table or related slice is empty.
PostParentId
1. This table or related slice is empty.
PostTypePostTypeId
1. PTQuestion
UserLastEditorUserId
1. USevilive
UserOwnerUserId
1. USevilive
plurals
PostLinksPostIdRelatedPostId
1. This table or related slice is empty.
PostLinksRelatedPostIdPostId
1. This table or related slice is empty.
PostsAcceptedAnswerId
1. This table or related slice is empty.
PostsParentIdCreationDate
1. PO
 singulars
 PostTypePostTypeId
 PTAnswer
VotesPostIdCreationDate
1. This table or related slice is empty.
CommentsPostId
1. COTried your code with driver v1.3.7, had no performance drop. Try this version.
 singulars
 PostPostId
 POExtremely slow MongoCursor::next() performance
 UserUserId
 USklkvsk

Querying!

Guidance

A row detail

Detail views are divided into sections. All the information in the data section comes from columns in the selected row. The other sections display data from other, related rows.

Related data can be related in a to-one or a to-many fashion. Captions of data related in a to-many fashion link to a list view showing a filtered view of the table.

Try moving around until you find a non-empty to-many entry and click on the label to get to one. You can move back to the root by clicking on the database name in the header.