[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: |
|
||
| Issue Links: |
|
||||||||||||
| 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 } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3884ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:817 nreturned:1 3229ms } bytes:20 nreturned:0 3685ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms |
| 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: } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:20 nreturned:0 3000ms } bytes:234 nreturned:2 11053ms and once the getMore appears, some simple operation will become slow also. like: , sort: { id: -1 }, update: { $inc: { id: 1 } }, new: true } reslen:91 204ms , sort: { id: -1 }, update: { $inc: { id: 1 } }, new: true } reslen:91 103ms , sort: { id: -1 }, update: { $inc: { id: 1 } }, new: true } reslen:91 161ms , 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 } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } bytes:20 nreturned:0 3979ms } } bytes:561 nreturned:1 3731ms } bytes:20 nreturned:0 3997ms } bytes:20 nreturned:0 3979ms } 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. |