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

createIndex blocks for duration of checkpoint while holding locks

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 3.2.5, 3.2.7
    • Fix Version/s: 3.2.12, 3.3.14
    • Component/s: WiredTiger
    • Labels:
      None
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Backport Completed:
    • Backport Requested:
      v3.2

      Description

      Test does some inserts to generate checkpoints of about 30 seconds, while doing createIndex about once per second:

      The createIndexes stall during checkpoints, which in turn stalls other operations because createIndex holds some locks.

      Stack traces collected during the stall show createIndex stuck waiting on a mutex in __wt_curfile_open:

      Thread 3 (Thread 0x7fe1682e1700 (LWP 22695)):
      #0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
      #1  0x00007fe16e399cfd in __GI___pthread_mutex_lock (mutex=0x32d6440) at ../nptl/pthread_mutex_lock.c:80
      #2  0x00000000019fe649 in __wt_curfile_open ()
      #3  0x0000000001a63a05 in __session_open_cursor_int ()
      #4  0x0000000001a14d33 in __wt_curtable_open ()
      #5  0x0000000001a63889 in __session_open_cursor_int ()
      #6  0x0000000001a63e19 in __session_open_cursor ()
      #7  0x0000000001066119 in mongo::WiredTigerIndex::BulkBuilder::openBulkCursor(mongo::WiredTigerIndex*) ()
      #8  0x000000000106137e in mongo::WiredTigerIndexStandard::getBulkBuilder(mongo::OperationContext*, bool) ()
      #9  0x0000000000c79fa9 in mongo::IndexAccessMethod::commitBulk(mongo::OperationContext*, std::unique_ptr<mongo::IndexAccessMethod::BulkBuilder, std::default_delete<mongo::IndexAccessMethod::BulkBuilder> >, bool, bool, std::set<mongo::RecordId, std::less<mongo::RecordId>, std::allocator<mongo::RecordId> >*) ()
      #10 0x0000000000ac29b0 in mongo::MultiIndexBlock::doneInserting(std::set<mongo::RecordId, std::less<mongo::RecordId>, std::allocator<mongo::RecordId> >*) ()
      #11 0x0000000000ac2f00 in mongo::MultiIndexBlock::insertAllDocumentsInCollection(std::set<mongo::RecordId, std::less<mongo::RecordId>, std::allocator<mongo::RecordId> >*) ()
      #12 0x0000000000aedf86 in mongo::CmdCreateIndex::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&) ()
      #13 0x0000000000b816e3 in mongo::Command::run(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*) ()
      #14 0x0000000000b82554 in mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*) ()
      #15 0x0000000000ad98c0 in mongo::runCommands(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*) ()
      #16 0x0000000000c9b095 in mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&) ()
      #17 0x0000000000961c2c in mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*) ()
      #18 0x00000000012b508d in mongo::PortMessageServer::handleIncomingMsg(void*) ()
      #19 0x00007fe16e3976aa in start_thread (arg=0x7fe1682e1700) at pthread_create.c:333
      #20 0x00007fe16e0cd13d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
      

      Here's the repro code:

      function insert(threads) {
          x = ''
          for (var i=0; i<1000; i++)
              x += 'x'
          docs = []
          for (var i=0; i<1000; i++)
              docs.push({x:x})
          ops = [{
              op: "insert",
              ns: "test.c",
              doc: docs,
          }]
          res = benchRun({
              ops: ops,
              seconds: 10000,
              parallel: threads
          })
          printjson(res)
      }
       
       
       
      function create() {
       
          for (var i=0; i<150; i++) {
       
              c = db['c'+i]
              t0 = new Date()
       
              print('createIndex at', t0)
              db['c'+i].createIndex({x:1})
       
              print('took', new Date() - t0, 'ms')
              sleep(1000)
       
          }
       
      }
      

        Issue Links

          Activity

          Hide
          michael.cahill Michael Cahill added a comment -

          Bruce Lucas, this was a conscious choice at some point in the WiredTiger layer between blocking and returning an EBUSY error.

          Bulk loads require exclusive access to the tree and enforce this with an exclusive handle lock. Unfortunately, checkpoints acquire shared locks on all handles, leading to the conflict. It happens that MongoDB can deal with an EBUSY in this situation by opening a non-bulk cursor, but it is potentially surprising that a background checkpoint can cause bulk loads to fail.

          One solution would be a "bulk=try" flag that first tries to open a bulk cursor, and if that would fail with EBUSY, falls back to an ordinary cursor.

          Show
          michael.cahill Michael Cahill added a comment - Bruce Lucas , this was a conscious choice at some point in the WiredTiger layer between blocking and returning an EBUSY error. Bulk loads require exclusive access to the tree and enforce this with an exclusive handle lock. Unfortunately, checkpoints acquire shared locks on all handles, leading to the conflict. It happens that MongoDB can deal with an EBUSY in this situation by opening a non-bulk cursor, but it is potentially surprising that a background checkpoint can cause bulk loads to fail. One solution would be a "bulk=try" flag that first tries to open a bulk cursor, and if that would fail with EBUSY , falls back to an ordinary cursor.
          Hide
          alexander.gorrod Alexander Gorrod added a comment -

          Michael Cahill I've opened WT-2781 to track adding functionality similar to what you describe above. I think this ticket can remain open, until the MongoDB portion of those changes is made.

          Show
          alexander.gorrod Alexander Gorrod added a comment - Michael Cahill I've opened WT-2781 to track adding functionality similar to what you describe above. I think this ticket can remain open, until the MongoDB portion of those changes is made.
          Hide
          xgen-internal-githook Githook User added a comment -

          Author:

          {u'username': u'sulabhM', u'name': u'Sulabh Mahajan', u'email': u'sulabh.mahajan@mongodb.com'}

          Message: SERVER-25012 Use non blocking call for opening bulk cursor to WT
          Branch: master
          https://github.com/mongodb/mongo/commit/d8ac57088d8eae13cf4bed7d9232bddea27e8052

          Show
          xgen-internal-githook Githook User added a comment - Author: {u'username': u'sulabhM', u'name': u'Sulabh Mahajan', u'email': u'sulabh.mahajan@mongodb.com'} Message: SERVER-25012 Use non blocking call for opening bulk cursor to WT Branch: master https://github.com/mongodb/mongo/commit/d8ac57088d8eae13cf4bed7d9232bddea27e8052
          Hide
          xgen-internal-githook Githook User added a comment -

          Author:

          {u'username': u'sulabhM', u'name': u'Sulabh Mahajan', u'email': u'sulabh.mahajan@mongodb.com'}

          Message: SERVER-25012 Use non blocking call for opening bulk cursor to WT

          (cherry picked from commit d8ac57088d8eae13cf4bed7d9232bddea27e8052)
          Branch: v3.2
          https://github.com/mongodb/mongo/commit/9969d473ffcf43d1014c3db13f5c639e83ee7df1

          Show
          xgen-internal-githook Githook User added a comment - Author: {u'username': u'sulabhM', u'name': u'Sulabh Mahajan', u'email': u'sulabh.mahajan@mongodb.com'} Message: SERVER-25012 Use non blocking call for opening bulk cursor to WT (cherry picked from commit d8ac57088d8eae13cf4bed7d9232bddea27e8052) Branch: v3.2 https://github.com/mongodb/mongo/commit/9969d473ffcf43d1014c3db13f5c639e83ee7df1

            People

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

              Dates

              • Created:
                Updated:
                Resolved: