Why are my MongoDB logs populated with "getmore local.oplog.rs"?

Question

This is repeated over and over in my MongoDB logs. Some notes:

• MongoDB 1.8.1 on Ubuntu 11.04
• Primary replica set
• 64 gigabyte drive
• RAM 5 GB
• new Date(5610408224193773570) always the same
• verbose = true commented out in the configuration file

It may be that my oplog is too large, so every time it does a secondary query it takes 4 seconds?

 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 

Answer 1

Given that the date is the same, it seems like the secondary one is requesting new oplog entries and just not getting anything. Do you write any data on the main?

The behavior looks a little unusual. However, I get the same thing by simply running the replica set and not recording it. The behavior you see is expected.