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

Logging "query admin.$cmd ntoreturn:1 command:..." shows extremely high ms response times

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 2.1.1
    • Affects Version/s: 1.7.5
    • Component/s: Sharding
    • None
    • Environment:
    • ALL

      Response times of e.g. 300028ms don't seem realistic

      From mongod slave during initial replica set sync:

      Mon Feb 21 21:04:47 [conn17] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5d5bb8c2504987772ec41b') }

      reslen:60 300028ms
      Mon Feb 21 21:04:49 [conn21] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5cf8b4b47bc4ea73aa83a1') }

      reslen:60 300027ms
      Mon Feb 21 21:05:20 [replica set sync] 1873579 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:05:29 [conn31] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5ba5a96ed04dfbd093cd97') }

      reslen:60 300029ms
      Mon Feb 21 21:06:21 [replica set sync] 2843732 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:06:21 [FileAllocator] allocating new datafile /mongodbdata/sd.4, filling with zeroes...
      Mon Feb 21 21:06:22 [FileAllocator] done allocating datafile /mongodbdata/sd.4, size: 1024MB, took 1.145 secs
      Mon Feb 21 21:07:22 [replica set sync] 3793311 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:07:45 [conn32] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5ba56021d7d00ef5bbe3b7') }

      reslen:60 300031ms
      Mon Feb 21 21:08:02 [conn33] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5a54108d4e400d241a4a83') }

      reslen:60 300032ms
      Mon Feb 21 21:08:24 [replica set sync] 4694503 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:09:25 [replica set sync] 5568644 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:09:46 [FileAllocator] allocating new datafile /mongodbdata/sd.5, filling with zeroes...
      Mon Feb 21 21:09:47 [conn17] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5d5bb8c2504987772ec41b') }

      reslen:60 300033ms
      Mon Feb 21 21:09:49 [conn21] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5cf8b4b47bc4ea73aa83a1') }

      reslen:60 300034ms
      Mon Feb 21 21:09:50 [FileAllocator] done allocating datafile /mongodbdata/sd.5, size: 2047MB, took 4.153 secs
      Mon Feb 21 21:10:27 [replica set sync] 6470217 objects cloned so far from collection sd.metrics
      Mon Feb 21 21:10:29 [conn31] query admin.$cmd ntoreturn:1 command:

      { writebacklisten: ObjectId('4d5ba5a96ed04dfbd093cd97') }

      reslen:60 300033ms

            Assignee:
            eliot Eliot Horowitz (Inactive)
            Reporter:
            boxedice David Mytton
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: