SpringData MongoDB – Infinite GetMore on Mongo Logs

javamongodb

Doing 2 queries on MongoDB through Spring Data on around 160 000 rows, query 1 is executed in few seconds (about 20 results) but query 2 never finish. I'm getting this line over and over on mongodb log:

Sun Apr 27 13:59:06.507 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 1 locks(micros) r:255198 nreturned:16 reslen:4264353 133ms
Sun Apr 27 13:59:16.125 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 3 locks(micros) r:242018 nreturned:16 reslen:4264832 131ms
Sun Apr 27 13:59:25.748 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 4 locks(micros) r:240837 nreturned:16 reslen:4264885 135ms
Sun Apr 27 13:59:35.496 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 2 locks(micros) r:195126 nreturned:16 reslen:4265303 114ms
Sun Apr 27 13:59:45.418 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 4 locks(micros) r:230168 nreturned:16 reslen:4265473 126ms
Sun Apr 27 13:59:55.007 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 2 locks(micros) r:228439 nreturned:16 reslen:4265817 135ms
Sun Apr 27 14:00:13.490 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 2 locks(micros) r:180845 nreturned:16 reslen:4265940 102ms
Sun Apr 27 14:00:32.978 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 2 locks(micros) r:132410 nreturned:16 reslen:4265572 106ms
Sun Apr 27 14:03:06.571 [conn16] getmore analysis.analysisDTO query: { annualPercent: { $gte: 5, $lte: 10 } } cursorid:12575735099603120 ntoreturn:0 keyUpdates:0 numYields: 2 locks(micros) r:205062 nreturned:16 reslen:4266662 107ms

Query 1:{ annualPercent: { $gte: 10, $lte: 1000000 } }

Query 2:{ annualPercent: { $gte: 5, $lte: 10 } }

I'm doing a big update of every rows just before theses queries, should I leave time to mongodb to re-index all ?

What the logs means ?

And how to solve that ?(I'm not using any special features of mongo driver or spring data)

Best Answer

The lines mean that each [getMore][1] (essentially each iteration on the cursor) is returning 16 documents and that each one is 4MB (the default max batch size limit). Essentially it is taking a little over 100ms to fetch the documents and return them, and they seem to be around 250KB each.

Note that the queries are yielding the lock, so they are likely not in memory and are being paged off disk (this is not the only reason that it might yield but it is the most likely).

Here's a quick breakdown of the interesting fields:

  • nreturned:16 = number of documents returned by the getmore
  • numYields: 4 = number of times that getmore yielded the lock
  • locks(micros) r:240837 = the time in microseconds that the read lock was held in total (r), which can be greater than the total execution time
  • reslen:4265572 = the size of the result in bytes (~4MB)
  • 135ms = the time to complete the getmore operation (100ms is the default threshold for logging slow queries)

If I were to hazard a guess I would think that the { $gte: 5, $lte: 10 } matches an awful lot more data than the { $gte: 10, $lte: 1000000 } criteria, and that all of that data is not fitting into memory, but it is hard to be sure with such a limited snapshot of the activity.

Related Question