Core Server
  1. Core Server
  2. SERVER-2232

Replication oplog sync log output more detailed

    Details

    • Type: Improvement Improvement
    • Status: Closed Closed
    • Priority: Minor - P4 Minor - P4
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.9.0
    • Component/s: Replication/Pairing
    • Labels:
      None
    • Backport:
      No
    • # Replies:
      2
    • Last comment by Customer:
      false

      Description

      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.

        Issue Links

          Activity

          Hide
          Reinaldo Giudici
          added a comment -

          Agree, and specially when the intiial sync is taking multiple days to complete.
          Is there actually any way to monitor where exactly the sync is ?
          The current status is only: "initial sync initial oplog application"

          Show
          Reinaldo Giudici
          added a comment - Agree, and specially when the intiial sync is taking multiple days to complete. Is there actually any way to monitor where exactly the sync is ? The current status is only: "initial sync initial oplog application"
          Hide
          auto
          added a comment -

          Author:

          {u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}

          Message: more detailed log output on initial sync SERVER-2232
          https://github.com/mongodb/mongo/commit/79d8885cadc7ce988909c601e82f52eefb01210e

          Show
          auto
          added a comment - Author: {u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'} Message: more detailed log output on initial sync SERVER-2232 https://github.com/mongodb/mongo/commit/79d8885cadc7ce988909c601e82f52eefb01210e

            People

            • Votes:
              1 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Days since reply:
                3 years, 4 weeks, 2 days ago
                Date of 1st Reply: