[SERVER-3148] Primary replica logs fill up with "getmore local.oplog.rs" Created: 26/May/11  Updated: 15/Aug/16  Resolved: 26/May/11

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 1.8.1
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Seamus Abshere Assignee: Kristina Chodorow (Inactive)
Resolution: Done Votes: 0
Labels: logging
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:
  • Ubuntu 11.04
  • Primary in a replica set
  • 64gb disk
  • 5gb RAM
  • verbose = true is commented out in the config file

Issue Links:
Duplicate
duplicates SERVER-4527 Suppress long query messages for oplo... Closed
Related
Operating System: ALL
Participants:

 Description   

I asked on StackOverflow (http://stackoverflow.com/questions/6118411/why-do-my-mongodb-logs-fill-up-with-getmore-local-oplog-rs) and people reported seeing the same thing, even on a totally new/fresh server.

This is repeated over and over again in my MongoDB logs on the primary replica. Note, also, that new Date(5610408224193773570) is always the same!

Wed May 25 00:35:58 [dur] lsn set 1552362
Wed May 25 00:36:02 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:06 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:11 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3884ms
Wed May 25 00:36:15 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:19 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:23 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:27 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:31 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:35 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:39 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:43 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:47 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:51 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:55 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:36:58 [dur] lsn set 1582372
Wed May 25 00:36:59 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:02 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:817 nreturned:1 3229ms
Wed May 25 00:37:06 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3685ms
Wed May 25 00:37:10 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:14 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:18 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:22 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:26 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:30 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:34 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:38 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:42 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:46 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:50 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:54 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:58 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Wed May 25 00:37:58 [dur] lsn set 1612372



 Comments   
Comment by Kristina Chodorow (Inactive) [ 18/Dec/12 ]

As described above, long getmores on the oplog are not an issue. Please ask on the mailing list (https://groups.google.com/forum/?fromgroups=#!forum/mongodb-user) if you have questions about slow queries.

Comment by skyloper [ 12/Dec/12 ]

Hi,Kristina,

we met the same problem days ago. our logs fill up the same logs, and we thought these oplog.rs getMore operations may effect the other requests. Here is our logs:
Wed Dec 12 11:05:47 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:05:47 [conn2440589] getmore local.oplog.rs cid:8951656207240660839 getMore: { ts:

{ $gte: new Date(5818650718562680857) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:06:48 [conn2440589] getmore local.oplog.rs cid:8951656207240660839 getMore: { ts:

{ $gte: new Date(5818650718562680857) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:07:01 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:07:52 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:07:52 [conn2440589] getmore local.oplog.rs cid:8951656207240660839 getMore: { ts:

{ $gte: new Date(5818650718562680857) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:08:09 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:08:15 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 11:08:23 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:20 nreturned:0 3000ms
Wed Dec 12 12:07:30 [conn2440592] getmore local.oplog.rs cid:180705592870967800 getMore: { ts:

{ $gte: new Date(5818650714267713588) }

} bytes:234 nreturned:2 11053ms

and once the getMore appears, some simple operation will become slow also. like:
Wed Dec 12 13:10:28 [conn2772629] query tt.$cmd ntoreturn:1 command: { findAndModify: "ids", query:

{ _id: "main" }

, sort:

{ id: -1 }

, update: { $inc:

{ id: 1 }

}, new: true } reslen:91 204ms
Wed Dec 12 13:10:28 [conn2773809] query tt.$cmd ntoreturn:1 command: { findAndModify: "ids", query:

{ _id: "main" }

, sort:

{ id: -1 }

, update: { $inc:

{ id: 1 }

}, new: true } reslen:91 103ms
Wed Dec 12 13:10:31 [conn2779540] query tt.$cmd ntoreturn:1 command: { findAndModify: "ids", query:

{ _id: "main" }

, sort:

{ id: -1 }

, update: { $inc:

{ id: 1 }

}, new: true } reslen:91 161ms
Wed Dec 12 13:10:32 [conn2773809] query tt.$cmd ntoreturn:1 command: { findAndModify: "ids", query:

{ _id: "main" }

, sort:

{ id: -1 }

, update: { $inc:

{ id: 1 }

}, new: true } reslen:91 157ms

How can we speed up the oplog getMore operations, and low the system io load ?

Comment by Kristina Chodorow (Inactive) [ 26/May/11 ]

No, you can't speed them up, sorry.

Comment by Seamus Abshere [ 26/May/11 ]

Thanks! I posted your explanation to the StackOverflow question.

If I want to speed up the long pulls, should I make the oplog smaller?

Comment by Kristina Chodorow (Inactive) [ 26/May/11 ]

So, the nreturned:1 is the document you just inserted. The time doesn't refresh because the cursor hasn't died. The cursor will probably die once your oplog is full and starts overwriting old entries.

Comment by Seamus Abshere [ 26/May/11 ]

Here's an example where the date does not advance after a write to the primary:

Thu May 26 15:28:47 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:28:51 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:28:55 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:28:59 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:29:03 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:29:03 [conn19] billing.MyCollection Btree::insert: key too large to index, skipping billing.MyCollection.$params_1 820 { :

{ acquisition: "2009-02-01", air_conditioner_use: "TURNED ON JUST ABOUT ALL SUMMER", annual_coal_volume_estimate: "0.0", annual_fuel_oil_cost: "100.0", annual_fuel_oil_volume_estimate: "0.0", annual_kerosene_volume_estimate: "0.0", annual_propane_cost: "100.0", annual_wood_volume_estimate: "0.0", clothes_drier_use: "3", construction_year: "2008-06-16", dishwasher_use: "4 TO 6 TIMES A WEEK", floors: "1", floorspace_estimate: "111.484", freezer_count: "1", monthly_electricity_cost: "150.0", monthly_natural_gas_cost: "50.0", monthly_natural_gas_volume_estimate: "0.0", occupation: "1.0", ownership: "false", refrigerator_count: "1", residence_class: "APARTMENT BUILDING WITH 5 OR MORE UNITS", residents: "3", timeframe: "2011-01-01/2012-01-01", urbanity: "TOWN", zip_code: "05753" }

}
Thu May 26 15:29:06 [initandlisten] connection accepted from 74.50.51.215:34221 #2207
Thu May 26 15:29:06 [conn2207] end connection 74.50.51.215:34221
Thu May 26 15:29:06 [initandlisten] connection accepted from 74.50.51.215:34224 #2208
Thu May 26 15:29:06 [conn2208] end connection 74.50.51.215:34224
Thu May 26 15:29:07 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:561 nreturned:1 3731ms
Thu May 26 15:29:11 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3997ms
Thu May 26 15:29:15 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms
Thu May 26 15:29:19 [conn14] getmore local.oplog.rs cid:265112601668423723 getMore: { ts:

{ $gte: new Date(5610408224193773570) }

} bytes:20 nreturned:0 3979ms

Note that something is returned... bytes:561... but the date stays the same.

Comment by Kristina Chodorow (Inactive) [ 26/May/11 ]

This is expected behavior. The slaves do long pulls from the master (notice each getMore is ~4 seconds). MongoDB logs queries that take longer than 100ms, so these are always logged. These queries aren't returning any new data (nreturned:0) so the point where the slave is querying doesn't change. If you do some writes on the primary, you'll see the date advance.

Generated at Thu Feb 08 03:02:12 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.