10

I am seeing the following in mongostat on the primary server in my replicate set:

insert  query update delete getmore command flushes mapped  vsize    res faults       locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn   set repl       time
     0    414    388      0    1218     444       0  24.2g  51.4g     3g      0  <redacted>:9.6%          0       0|0     0|0   225k   441k   463 mover  PRI   03:26:30
     0    469    457      0    1352     516       0  24.2g  51.4g     3g      0 <redacted>:10.6%          0       0|0     0|0   258k   498k   463 mover  PRI   03:26:31
     0    478    482      0    1430     548       0  24.2g  51.4g     3g      0 <redacted>:12.0%          0       0|0     0|0   271k   512k   463 mover  PRI   03:26:32

As you can see the getmore count is dominating any other form of operation. This is something that has just recently started happening, as can be seen in the attached graph of opcounters. From what I've read these might be from the replica set operations, but for my piece of mind I would like to find a way to confirm that. Is there anyway I can determine the source of these getmore ops?

enter image description here

UPDATE: Added a new screenshot of opcounters from MMS which includes the legend.

General Grievance
  • 4,555
  • 31
  • 31
  • 45
Ben Zittlau
  • 2,345
  • 1
  • 21
  • 30

2 Answers2

15

A getmore indicates that a "next batch of results" was fetched from an open cursor. This may indicate either a large result set where your application has to fetch several batches, or a long running operation such as replication tailing the oplog.

Given there is a large jump starting from the 26th Jan, I would consider if you changed anything in your application or usage that might correlate with this change. Perhaps you started a new backup routine, or one of your common queries now has enough data to require multiple batches.

If you want to determine the source of the increased getmore count, you can see these logged at logLevel 1 or higher.

The logLevel parameter can be set on startup or adjusted at runtime. The logs will get large quickly with the extra detail, so I would suggest increasing for a short period of time to sample getmores during one of the peak periods indicated in MMS.

To increase logLevel in the mongo shell use:

db.adminCommand( { setParameter: 1, logLevel: 1 } )

You can change back to the default logLevel with:

db.adminCommand( { setParameter: 1, logLevel: 0 } )

After increasing the logLevel, you should be able to grep your mongod log for lines with "getmore" which will be similar to:

Sun Feb  9 09:31:14.573 [conn8527] getmore local.oplog.rs query: { .. }

The text after "getmore" (and before the query) indicates the namespace (i.e. "database.collection").

The getmore queries from replication or any other applications tailing the oplog (such as MMS Backup or MongoDB Connector) will always be on the local.oplog.rs namespace.

Stennie
  • 63,885
  • 14
  • 149
  • 175
  • Thank you! I'd actually never heard of that logLevel setting, and this was exactly what I needed. Turns out the getmore ops are all against the local.oplog.rs namespace. I want to dig into further why they've become so aggressive, but I'll cover that in another question. – Ben Zittlau Feb 20 '14 at 01:24
4

Mileage may vary on this, but I would have expected large getmore counts to be merely an indicator of how many results where being fetched. It is by definition a cursor batch request, and the most direct correlation I would see is expecting this to be a multiple of the number of query operations. And yes this would include replication as well, as queries would be issued to the oplog by secondaries.

This makes sense as each query is going to set up a cursor to return results, that batch is going to be fetched and when exhausted the new op is going to issue. Now it would be fair to say that it would be optimal for the larger portion of queries to utilize a minimal number of getmore ops per request, but that may not be the most practical approach. As said, YMMV.

Therefore I suppose one correlation for your "Peace of Mind", would be to look at the queries being executed, the sort of data being returned and the number of results. Getting at that information is a matter of playing with the Database Profiler and then playing around with the results found.

Data in the oplog should also correlate to high count times where there are spikes in replication operations, so you should be able to see what the impact of that is as well.

Neil Lunn
  • 148,042
  • 36
  • 346
  • 317
  • I realized that the screenshot I included from MMS didn't have the legend so may not have been clear (and have updated it in the original post). The getmore operations are changing dramatically independent of changes to the other operation counts, which is the major source of my concern. That's why I'm looking for a method to find the cause of the getmore operations. – Ben Zittlau Feb 07 '14 at 17:47
  • I think that if you are looking for someone to answer and say "This is the reason this is happening.." then that isn't going to happen. The only person who can really tell what is happening in your environment is you. Others can only give you an idea where to look and what to look for. As I explained, you could have large numbers of this op on say "queries" without the number of queries increasing. It's about cursor page fetches. More results, more fetches. That is something to look for in your logs. – Neil Lunn Feb 07 '14 at 19:33
  • If you read the question you will find that I am asking for approaches to be able to diagnose the source of the problem, not a magical answer. – Ben Zittlau Feb 20 '14 at 01:12
  • @BenZittlau If you read the answers two people explained what getMore was and where to look. My omission was presuming you knew about setting the logLevel. But hopefully you are on the right track now. – Neil Lunn Feb 20 '14 at 03:22