Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-2232

Replication oplog sync log output more detailed

    • Type: Icon: Improvement Improvement
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 1.9.0
    • Affects Version/s: None
    • Component/s: Replication
    • None

      The log output when a replica set has completed the initial clone and is now running through the oplog is not very detailed. E.g. I had no idea what was happening for 25 minutes here:

      Thu Dec 16 07:45:55 [replica set sync] replSet initial sync cloning db: admin
      Thu Dec 16 07:45:55 [replica set sync] replSet initial sync cloning db: test
      Thu Dec 16 07:45:55 [replica set sync] replSet initial sync query minValid
      Thu Dec 16 07:45:55 [replica set sync] replSet initial sync initial oplog application
      Thu Dec 16 08:09:34 [replica set sync] building new index on

      { _id: 1 }

      for postbacks.postbacks
      Thu Dec 16 08:09:35 [replica set sync] done for 108421 records 0.465secs
      Thu Dec 16 08:09:55 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 187ms
      Thu Dec 16 08:10:01 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 180ms
      Thu Dec 16 08:10:08 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 127ms
      Thu Dec 16 08:10:11 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 330ms
      Thu Dec 16 08:10:35 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 109ms
      Thu Dec 16 08:10:39 allocating new datafile /mongodbdata/sd.2, filling with zeroes...
      Thu Dec 16 08:10:39 done allocating datafile /mongodbdata/sd.2, size: 256MB, took 0.244 secs
      Thu Dec 16 08:10:44 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 206ms
      Thu Dec 16 08:10:45 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 187ms
      Thu Dec 16 08:10:46 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 136ms
      Thu Dec 16 08:10:50 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 136ms
      Thu Dec 16 08:10:51 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 187ms
      Thu Dec 16 08:10:54 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 188ms
      Thu Dec 16 08:11:01 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 114ms
      Thu Dec 16 08:11:03 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 169ms
      Thu Dec 16 08:11:11 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 120ms
      Thu Dec 16 08:11:18 [replica set sync] replSet initialSyncOplogApplication 100000
      Thu Dec 16 08:11:21 [conn3] query admin.$cmd ntoreturn:1 command:

      { serverStatus: 1 }

      reslen:1181 211ms
      Thu Dec 16 08:12:01 [replica set sync] replSet initial sync finishing up
      Thu Dec 16 08:12:02 [replica set sync] replSet set minValid=4d09c3b3:af
      Thu Dec 16 08:12:02 [replica set sync] building new index on

      { _id: 1 }

      for local.replset.minvalid
      Thu Dec 16 08:12:03 [replica set sync] done for 0 records 0.074secs
      Thu Dec 16 08:12:03 [replica set sync] replSet initial sync done
      Thu Dec 16 08:12:04 [replica set sync] replSet SECONDARY

      It would be useful to output more about what is happening and the % complete.

            Assignee:
            kristina Kristina Chodorow (Inactive)
            Reporter:
            boxedice David Mytton
            Votes:
            1 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: