1.8 Replica Sets go out of sync after 1 hour under load

[Chase]

We have found an issue with the replica sets going out of sync after
approximately 1 hour under high load. In the slave we get the
following in the log:

Sun Apr 24 20:44:42 [FileAllocator] allocating new datafile /data/
sessions.1/session_cache.5, filling with zeroes...
Sun Apr 24 20:44:46 [FileAllocator] done allocating datafile /data/
sessions.1/session_cache.5, size: 2047MB, took 4.217 secs
Sun Apr 24 20:54:31 [conn142] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 145ms
Sun Apr 24 20:54:37 [conn144] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 109ms
Sun Apr 24 20:55:30 [conn146] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 200ms
Sun Apr 24 20:55:38 [conn150] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 853ms
Sun Apr 24 20:58:30 [conn164] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 360ms
Sun Apr 24 21:10:43 [conn268] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 285ms
Sun Apr 24 21:10:43 [conn267] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 314ms
Sun Apr 24 21:10:43 [conn269] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 279ms
Sun Apr 24 21:10:46 [conn270] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 150ms
Sun Apr 24 21:12:32 [conn278] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 335ms
Sun Apr 24 21:20:41 [conn337] query admin.$cmd ntoreturn:1 command:
{ serverStatus: 1 } reslen:1368 538ms
Sun Apr 24 21:22:55 [replica set sync] repl: old cursor isDead, will
initiate a new one
Sun Apr 24 21:22:56 [replica set sync] replSet error RS102 too stale
to catch up, at least from sessionmgr01:27717
Sun Apr 24 21:22:56 [replica set sync] replSet our last optime : Apr
24 21:17:08 4db4e7b4:54
Sun Apr 24 21:22:56 [replica set sync] replSet oldest at
sessionmgr01:27717 : Apr 24 21:17:11 4db4e7b7:4f7
Sun Apr 24 21:22:56 [replica set sync] replSet See
http://www.mongodb.org/display/DOCS/Resyncing+a+Very+Stale+Replica+Set+Member
Sun Apr 24 21:22:56 [replica set sync] replSet error RS102 too stale
to catch up
Sun Apr 24 21:22:56 [replica set sync] replSet RECOVERING

In the master the following is found:

Sun Apr 24 21:22:49 [conn35] getmore local.oplog.rs cid:
968739367957150436 getMore: { ts: { $gte: new
Date(5599344019072101879) } } bytes:4194364 nreturned:5506 3902ms
Sun Apr 24 21:22:55 [conn35] getmore local.oplog.rs cid:
968739367957150436 getMore: { ts: { $gte: new
Date(5599344019072101879) } } bytes:62797 nreturned:96 4185ms
Sun Apr 24 21:22:55 [conn35] getMore: cursorid not found
local.oplog.rs 968739367957150436
Sun Apr 24 21:22:56 [ReplSetHealthPollTask] replSet member
sessionmgr02:27717 RECOVERING

Our oplog is sized at 1 GB which should fill up in about 3 minutes
based on the size of the records we are inserting and updating. Is
there any approach to determine how far behind a replica is and also
determine why it is not catching up. The replica is on identical
hardware as the master.

[Eliot Horowitz]

3 minutes of oplog is probably way too small.
We usually recommend numbers in the hours - ideally a day even.

You can figure out how far behind it is by looking at rs.status()

In terms of why it can't keep up in that 3 minute window, there could
be a lot of reasons.
First, are the in the same data center? What's the ping time between them?
Can you check disk/cpu usage on the slave?

> --
> You received this message because you are subscribed to the Google Groups "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com.
> To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
>
>

[Chase]

Hi Eliot - The slave seems to fall consistently behind. The following
is the optimes between master / slave:

"optimeDate" :
ISODate("2011-04-25T16:33:13Z"),
"optimeDate" :
ISODate("2011-04-25T16:31:18Z"),

"optimeDate" :
ISODate("2011-04-25T16:34:41Z"),
"optimeDate" :
ISODate("2011-04-25T16:31:32Z"),

"optimeDate" :
ISODate("2011-04-25T16:37:07Z"),
"optimeDate" :
ISODate("2011-04-25T16:33:17Z"),

"optimeDate" :
ISODate("2011-04-25T16:44:17Z"),
"optimeDate" :
ISODate("2011-04-25T16:35:36Z"),


The machines connected via a 1 gig switch and are in the same physical
blade chasis. We are sending about 100 megabits/ sec across the
connection. Ping time is approximately .5ms. Our monitoring shows
that the master is running at 30% idle and the slave is 50% idle (with
more peaks / valleys in the slave cpu graph). Io wait time on the
master is around 20% and the slave is around 15%. We are running
around 3,000 write operations per second to this set. As a side note,
we have another replica set on the same set o machines that is running
a similar number of writes (but no indexes on the collection it is
replicating) and it is completely synced up.

> >http://www.mongodb.org/display/DOCS/Resyncing+a+Very+Stale+Replica+Se...

[Eliot Horowitz]

Can you send a larger log sample from the slave?
Those %s, are those disk/cpu?