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

Inner Collection (w/ > 10000 entries) with Indexed Fields Dramatically hurt performance when adding new fields on the outer document or entries in the inner collection

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Critical - P2
    • Resolution: Duplicate
    • 2.2.0-rc0, 2.2.0
    • None
    • None
    • None
    • Behavior witnessed on OS X & Ubuntu 12.04
    • ALL

    Description

      The following has been tested on mongoDB v2.2.0rc0 & mongoDB v2.2.0:

          1. The test:

      First initialize the database:

      > use test
      > db.dropDatabase()
      > db.createCollection('testdocuments')
      > db.testdocuments.insert(

      { _id : ObjectId("000000000000000000000001") }

      )

      Then populate a document's inner collection with objects:

      > for ( var i = 1; i < 10000; i++) { db.testdocuments.update(

      { _id : ObjectId("000000000000000000000001") }

      , { $push : { 'a' :

      { uid1 : i, uid2: i }

      } }) }

      Then add a new outer field:

      > db.testdocuments.update(

      { _id : ObjectId("000000000000000000000001") }

      , { $set :

      { 'aNewOuterField' : 1 }

      })

      All is well and the update takes normal time. But, if those inner documents are indexed:

      > db.testdocuments.ensureIndex(

      { 'a.uid1' : 1 }

      )

      mongodb-console-> Thu Aug 30 14:17:31 [conn4] build index test.testdocuments

      { a.uid1: 1.0 }

      mongodb-console-> Thu Aug 30 14:17:34 [conn4] build index done. scanned 1 total records. 2.244 secs
      mongodb-console-> Thu Aug 30 14:17:34 [conn4] insert test.system.indexes keyUpdates:0 locks(micros) w:2244536 2244ms

      and we add another outer field :

      > db.testdocuments.update(

      { _id : ObjectId("000000000000000000000001") }

      , { $set :

      { 'anotherOuterField' : 1 }

      })

      Then we get the MongoDB console reporting the action as slow:

      mongodb-console-> Thu Aug 30 14:20:01 [conn4] update test.testdocuments query:

      { _id: ObjectId('000000000000000000000001') }

      update: { $set:

      { anotherOuterField: 1.0 }

      } idhack:1 nupdated:1 keyUpdates:0 locks(micros) w:4191036 4191ms

      Indeed, the last operation has been reported to have taken more than 4 seconds even though there was no index modification at all.

      This might be due to the document being moved but setting the profiler 'on',

      > db.setProfilingLevel(1)

      and adding another outer field:

      > db.testdocuments.update(

      { _id : ObjectId("000000000000000000000001") }

      , { $set :

      { 'oneLastOuterField' : 1 }

      })

      gives us the following:

      > db.system.profile.find().pretty()

      {
      "ts" : ISODate("2012-08-30T18:23:03.053Z"),
      "op" : "update",
      "ns" : "test.testdocuments",
      "query" :

      { "_id" : ObjectId("000000000000000000000001") }

      ,
      "updateobj" : {
      "$set" :

      { "oneLastOuterField" : 1 }

      },
      "idhack" : true,
      "nupdated" : 1,
      "keyUpdates" : 0,
      "numYield" : 0,
      "lockStats" : {
      "timeLockedMicros" :

      { "r" : NumberLong(0), "w" : NumberLong(4064791) }

      ,
      "timeAcquiringMicros" :

      { "r" : NumberLong(0), "w" : NumberLong(47) }

      },
      "millis" : 4064,
      "client" : "127.0.0.1",
      "user" : ""
      }

      which definitely shows that the delay isn't due to the document being 'moved'.

      Adding to the inner collection is not faster either as

      > db.testdocuments.update(

      { _id : ObjectId("000000000000000000000001") }

      , { $push : { 'a' :

      { uid1 : -1, uid2: -1 }

      } })

      gives us the following profile

      > db.system.profile.find().pretty()

      {
      "ts" : ISODate("2012-08-30T18:32:34.080Z"),
      "op" : "update",
      "ns" : "test.testdocuments",
      "query" :

      { "_id" : ObjectId("000000000000000000000001") }

      ,
      "updateobj" : {
      "$push" : {
      "a" :

      { "uid1" : -1, "uid2" : -1 }

      }
      },
      "nscanned" : 1,
      "nupdated" : 1,
      "keyUpdates" : 1,
      "numYield" : 0,
      "lockStats" : {
      "timeLockedMicros" :

      { "r" : NumberLong(0), "w" : NumberLong(4057496) }

      ,
      "timeAcquiringMicros" :

      { "r" : NumberLong(0), "w" : NumberLong(213) }

      },
      "millis" : 4057,
      "client" : "127.0.0.1",
      "user" : ""
      }

      Attachments

        Issue Links

          Activity

            People

              aaron Aaron Staple
              glesperance Gabriel Lesperance
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: