[SERVER-2321] Don't run through entire oplog if not necessary Created: 03/Jan/11  Updated: 30/Mar/12  Resolved: 03/Jan/11

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

Type: Improvement Priority: Minor - P4
Reporter: David Mytton Assignee: Kristina Chodorow (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   
  • First oplog entry is 1st Jan 00:00:00
  • I start an initial sync on 3rd Jan 00:00:00 which finishes 10 minutes later.

Currently mongo will run through the entire oplog from 1st Jan 00:00:00 even though it's only necessary to start from 3rd Jan 00:00:00. This is a problem when the oplog is large because it's slower than it needs to be.



 Comments   
Comment by David Mytton [ 03/Jan/11 ]

It doesn't do it when you take a slave offline then bring it back online after a few minutes - doesn't seem to loop through the whole oplog. Only when it's done an initial clone and sync.

But I am running pre-1.7.2.

Comment by Eliot Horowitz (Inactive) [ 03/Jan/11 ]

shouldn't be the case.
might have been something fixed in 1.7.x

Comment by David Mytton [ 03/Jan/11 ]

Yes. Initial sync completed and oplog catchup taking place:

Mon Jan 3 16:24:41 [rs_sync] done for 0 records 0secs
Mon Jan 3 16:24:41 [rs_sync] replSet initial sync cloning db: admin
Mon Jan 3 16:24:41 [rs_sync] replSet initial sync query minValid
Mon Jan 3 16:24:41 [rs_sync] replSet initial sync copy+apply oplog
Mon Jan 3 16:24:50 [rs_sync] replSet initialSyncOplogApplication 100000
Mon Jan 3 16:24:59 [rs_sync] replSet initialSyncOplogApplication 200000
Mon Jan 3 16:25:06 [rs_sync] replSet initialSyncOplogApplication 300000
Mon Jan 3 16:25:10 [conn4] query admin.$cmd ntoreturn:1 command:

{ replSetHeartbeat: "set2", v: 6, pv: 1, checkEmpty: false, from: "rs2arbiter:27018" }

reslen:161 0ms
Mon Jan 3 16:25:15 [rs_sync] replSet initialSyncOplogApplication 400000
Mon Jan 3 16:25:23 [rs_sync] replSet initialSyncOplogApplication 500000
Mon Jan 3 16:25:31 [rs_sync] replSet initialSyncOplogApplication 600000
Mon Jan 3 16:25:39 [rs_sync] replSet initialSyncOplogApplication 700000
Mon Jan 3 16:25:49 [rs_sync] replSet initialSyncOplogApplication 800000
Mon Jan 3 16:25:56 [rs_sync] replSet initialSyncOplogApplication 900000
Mon Jan 3 16:26:05 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 114ms
Mon Jan 3 16:26:05 [rs_sync] replSet initialSyncOplogApplication 1000000
Mon Jan 3 16:26:12 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 188ms
Mon Jan 3 16:26:13 [rs_sync] replSet initialSyncOplogApplication 1100000
Mon Jan 3 16:26:19 [rs_sync] replSet initialSyncOplogApplication 1200000
Mon Jan 3 16:26:28 [rs_sync] replSet initialSyncOplogApplication 1300000
Mon Jan 3 16:26:35 [rs_sync] replSet initialSyncOplogApplication 1400000
Mon Jan 3 16:26:41 [rs_sync] replSet initialSyncOplogApplication 1500000
Mon Jan 3 16:26:42 [rs_sync] replSet initialSyncOplogApplication 1600000
Mon Jan 3 16:26:44 [rs_sync] replSet initialSyncOplogApplication 1700000
Mon Jan 3 16:26:53 [rs_sync] replSet initialSyncOplogApplication 1800000
Mon Jan 3 16:27:02 [rs_sync] replSet initialSyncOplogApplication 1900000
Mon Jan 3 16:27:08 [rs_sync] replSet initialSyncOplogApplication 2000000
Mon Jan 3 16:27:17 [rs_sync] replSet initialSyncOplogApplication 2100000
Mon Jan 3 16:27:24 [rs_sync] replSet initialSyncOplogApplication 2200000
Mon Jan 3 16:27:31 [rs_sync] replSet initialSyncOplogApplication 2300000
Mon Jan 3 16:27:39 [rs_sync] replSet initialSyncOplogApplication 2400000
Mon Jan 3 16:27:48 [rs_sync] replSet initialSyncOplogApplication 2500000
Mon Jan 3 16:27:54 [rs_sync] replSet initialSyncOplogApplication 2600000
Mon Jan 3 16:28:03 [rs_sync] replSet initialSyncOplogApplication 2700000
Mon Jan 3 16:28:10 [rs_sync] replSet initialSyncOplogApplication 2800000
Mon Jan 3 16:28:19 [rs_sync] replSet initialSyncOplogApplication 2900000
Mon Jan 3 16:28:25 [rs_sync] replSet initialSyncOplogApplication 3000000
Mon Jan 3 16:28:25 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 102ms
Mon Jan 3 16:28:27 [rs_sync] replSet initialSyncOplogApplication 3100000
Mon Jan 3 16:28:33 [rs_sync] replSet initialSyncOplogApplication 3200000
Mon Jan 3 16:28:35 [conn2] query admin.$cmd ntoreturn:1 command:

{ replSetHeartbeat: "set2", v: 6, pv: 1, checkEmpty: false, from: "rs2b:27018" }

reslen:132 0ms
Mon Jan 3 16:28:37 [rs_sync] replSet initialSyncOplogApplication 3300000
Mon Jan 3 16:28:42 [rs_sync] replSet initialSyncOplogApplication 3400000
Mon Jan 3 16:28:44 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 149ms
Mon Jan 3 16:28:48 [rs_sync] replSet initialSyncOplogApplication 3500000
Mon Jan 3 16:28:52 [rs_sync] replSet initialSyncOplogApplication 3600000
Mon Jan 3 16:28:56 [rs_sync] replSet initialSyncOplogApplication 3700000
Mon Jan 3 16:29:01 [rs_sync] replSet initialSyncOplogApplication 3800000
Mon Jan 3 16:29:04 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 116ms
Mon Jan 3 16:29:09 [rs_sync] replSet initialSyncOplogApplication 3900000
Mon Jan 3 16:29:16 [rs_sync] replSet initialSyncOplogApplication 4000000
Mon Jan 3 16:29:24 [rs_sync] replSet initialSyncOplogApplication 4100000
Mon Jan 3 16:29:31 [rs_sync] replSet initialSyncOplogApplication 4200000
Mon Jan 3 16:29:39 [rs_sync] replSet initialSyncOplogApplication 4300000
Mon Jan 3 16:29:47 [rs_sync] replSet initialSyncOplogApplication 4400000
Mon Jan 3 16:29:54 [rs_sync] replSet initialSyncOplogApplication 4500000
Mon Jan 3 16:29:58 [rs_sync] replSet initialSyncOplogApplication 4600000
Mon Jan 3 16:30:01 [rs_sync] replSet initialSyncOplogApplication 4700000
Mon Jan 3 16:30:05 [rs_sync] replSet initialSyncOplogApplication 4800000
Mon Jan 3 16:30:08 [rs_sync] replSet initialSyncOplogApplication 4900000
Mon Jan 3 16:30:09 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 263ms
Mon Jan 3 16:30:11 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 183ms
Mon Jan 3 16:30:12 [rs_sync] replSet initialSyncOplogApplication 5000000
Mon Jan 3 16:30:20 [rs_sync] replSet initialSyncOplogApplication 5100000
Mon Jan 3 16:30:29 [rs_sync] replSet initialSyncOplogApplication 5200000
Mon Jan 3 16:30:39 [rs_sync] replSet initialSyncOplogApplication 5300000
Mon Jan 3 16:30:48 [rs_sync] replSet initialSyncOplogApplication 5400000
Mon Jan 3 16:30:55 [rs_sync] replSet initialSyncOplogApplication 5500000
Mon Jan 3 16:31:03 [rs_sync] replSet initialSyncOplogApplication 5600000
Mon Jan 3 16:31:11 [rs_sync] replSet initialSyncOplogApplication 5700000
Mon Jan 3 16:31:19 [rs_sync] replSet initialSyncOplogApplication 5800000
Mon Jan 3 16:31:27 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 143ms
Mon Jan 3 16:31:28 [rs_sync] replSet initialSyncOplogApplication 5900000
Mon Jan 3 16:31:38 [rs_sync] replSet initialSyncOplogApplication 6000000
Mon Jan 3 16:31:45 [rs_sync] replSet initialSyncOplogApplication 6100000
Mon Jan 3 16:31:53 [rs_sync] replSet initialSyncOplogApplication 6200000
Mon Jan 3 16:32:01 [conn3] query admin.$cmd ntoreturn:1 command:

{ replSetHeartbeat: "set2", v: 6, pv: 1, checkEmpty: false, from: "rs2d:27018" }

reslen:132 0ms
Mon Jan 3 16:32:01 [rs_sync] replSet initialSyncOplogApplication 6300000
Mon Jan 3 16:32:06 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 141ms
Mon Jan 3 16:32:09 [rs_sync] replSet initialSyncOplogApplication 6400000
Mon Jan 3 16:32:13 [rs_sync] replSet initialSyncOplogApplication 6500000
Mon Jan 3 16:32:16 [rs_sync] replSet initialSyncOplogApplication 6600000
Mon Jan 3 16:32:19 [rs_sync] replSet initialSyncOplogApplication 6700000
Mon Jan 3 16:32:24 [rs_sync] replSet initialSyncOplogApplication 6800000
Mon Jan 3 16:32:32 [rs_sync] replSet initialSyncOplogApplication 6900000
Mon Jan 3 16:32:40 [rs_sync] replSet initialSyncOplogApplication 7000000
Mon Jan 3 16:32:50 [rs_sync] replSet initialSyncOplogApplication 7100000
Mon Jan 3 16:32:56 [rs_sync] replSet initialSyncOplogApplication 7200000
Mon Jan 3 16:33:05 [rs_sync] replSet initialSyncOplogApplication 7300000
Mon Jan 3 16:33:12 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 128ms
Mon Jan 3 16:33:12 [rs_sync] replSet initialSyncOplogApplication 7400000
Mon Jan 3 16:33:21 [rs_sync] replSet initialSyncOplogApplication 7500000
Mon Jan 3 16:33:28 [rs_sync] replSet initialSyncOplogApplication 7600000
Mon Jan 3 16:33:36 [rs_sync] replSet initialSyncOplogApplication 7700000
Mon Jan 3 16:33:44 [rs_sync] replSet initialSyncOplogApplication 7800000
Mon Jan 3 16:33:53 [rs_sync] replSet initialSyncOplogApplication 7900000
Mon Jan 3 16:34:01 [rs_sync] replSet initialSyncOplogApplication 8000000
Mon Jan 3 16:34:07 [rs_sync] replSet initialSyncOplogApplication 8100000
Mon Jan 3 16:34:15 [rs_sync] replSet initialSyncOplogApplication 8200000
Mon Jan 3 16:34:22 [rs_sync] replSet initialSyncOplogApplication 8300000
Mon Jan 3 16:34:28 [rs_sync] replSet initialSyncOplogApplication 8400000
Mon Jan 3 16:34:33 [rs_sync] replSet initialSyncOplogApplication 8500000
Mon Jan 3 16:34:37 [rs_sync] replSet initialSyncOplogApplication 8600000
Mon Jan 3 16:34:40 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 214ms
Mon Jan 3 16:34:42 [rs_sync] replSet initialSyncOplogApplication 8700000
Mon Jan 3 16:34:46 [rs_sync] replSet initialSyncOplogApplication 8800000
Mon Jan 3 16:34:52 [rs_sync] replSet initialSyncOplogApplication 8900000
Mon Jan 3 16:34:59 [rs_sync] replSet initialSyncOplogApplication 9000000
Mon Jan 3 16:35:00 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 127ms
Mon Jan 3 16:35:05 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 120ms
Mon Jan 3 16:35:07 [rs_sync] replSet initialSyncOplogApplication 9100000
Mon Jan 3 16:35:08 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 111ms
Mon Jan 3 16:35:14 [rs_sync] replSet initialSyncOplogApplication 9200000
Mon Jan 3 16:35:20 [rs_sync] replSet initialSyncOplogApplication 9300000
Mon Jan 3 16:35:23 [rs_sync] replSet initialSyncOplogApplication 9400000
Mon Jan 3 16:35:26 [conn3] query admin.$cmd ntoreturn:1 command:

{ replSetHeartbeat: "set2", v: 6, pv: 1, checkEmpty: false, from: "rs2d:27018" }

reslen:132 0ms
Mon Jan 3 16:35:27 [rs_sync] replSet initialSyncOplogApplication 9500000
Mon Jan 3 16:35:29 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 125ms
Mon Jan 3 16:35:30 [rs_sync] replSet initialSyncOplogApplication 9600000
Mon Jan 3 16:35:35 [rs_sync] replSet initialSyncOplogApplication 9700000
Mon Jan 3 16:35:41 [rs_sync] replSet initialSyncOplogApplication 9800000
Mon Jan 3 16:35:48 [rs_sync] replSet initialSyncOplogApplication 9900000
Mon Jan 3 16:35:53 [rs_sync] replSet initialSyncOplogApplication 10000000
Mon Jan 3 16:35:58 [rs_sync] replSet initialSyncOplogApplication 10100000
Mon Jan 3 16:36:04 [rs_sync] replSet initialSyncOplogApplication 10200000
Mon Jan 3 16:36:08 [rs_sync] replSet initialSyncOplogApplication 10300000
Mon Jan 3 16:36:14 [rs_sync] replSet initialSyncOplogApplication 10400000
Mon Jan 3 16:36:15 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 174ms
Mon Jan 3 16:36:20 [rs_sync] replSet initialSyncOplogApplication 10500000
Mon Jan 3 16:36:21 [conn5] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1145 235ms
Mon Jan 3 16:36:26 [rs_sync] replSet initialSyncOplogApplication 10600000
Mon Jan 3 16:36:32 [rs_sync] replSet initialSyncOplogApplication 10700000
Mon Jan 3 16:36:38 [rs_sync] replSet initialSyncOplogApplication 10800000
Mon Jan 3 16:36:44 [rs_sync] replSet initialSyncOplogApplication 10900000
Mon Jan 3 16:36:51 [rs_sync] replSet initialSyncOplogApplication 11000000
Mon Jan 3 16:36:57 [rs_sync] replSet initialSyncOplogApplication 11100000

rs.status() output from the master being sync'd from:

> rs.status()
{
"set" : "set2",
"date" : ISODate("2011-01-03T16:25:39Z"),
"myState" : 1,
"members" : [
{
"_id" : 0,
"name" : "rs2a:27018",
"health" : 1,
"state" : 3,
"stateStr" : "RECOVERING",
"uptime" : 230,
"optime" :

{ "t" : 1293048616000, "i" : 209 }

,
"optimeDate" : ISODate("2010-12-22T20:10:16Z"),
"lastHeartbeat" : ISODate("2011-01-03T16:25:37Z"),
"errmsg" : "initial sync copy+apply oplog"
},

optimeDate shows the first entry in the oplog. Refreshing this over the last hour shows it moving forward in time to the current:

> rs.status()
{
"set" : "set2",
"date" : ISODate("2011-01-03T17:33:15Z"),
"myState" : 1,
"members" : [
{
"_id" : 0,
"name" : "rs2a:27018",
"health" : 1,
"state" : 3,
"stateStr" : "RECOVERING",
"uptime" : 4286,
"optime" :

{ "t" : 1293930027000, "i" : 54 }

,
"optimeDate" : ISODate("2011-01-02T01:00:27Z"),
"lastHeartbeat" : ISODate("2011-01-03T17:33:14Z")
},

Comment by Eliot Horowitz (Inactive) [ 03/Jan/11 ]

It in fact does only take the last section.

Do you have logs or something showing otherwise?

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