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

rc10/wiredTiger multi collection/DB bulk insert slow than rc8 in initial insertion phase

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical - P2
    • Resolution: Fixed
    • Affects Version/s: 3.0.0-rc10
    • Fix Version/s: 3.0.2, 3.1.1
    • Component/s: WiredTiger
    • Labels:
    • Backwards Compatibility:
      Fully Compatible
    • Operating System:
      ALL
    • Backport Completed:

      Description

      re-test rc10 for SERVER-17344, see improvement with insert throughput, but overall still slower than that of RC8.

      version insert throughput
      rc8 94,069.51
      rc9 57,129.39
      rc10 66,562.25

      after debug, found out that rc10

      • have much higher percentage of very slow insert (> 1 sec), see the attached chart from mtools.
      • is very slow for the first few minutes, it recovers and stabilizes after few minutes.

      Combine this with the way sysbench insert is designed (pin one thread one collection), it could amplify the impact in overall throughput.

      Run bulk insert with benchRun show insert throughput is similar between rc10 & rc8.

      I think the high number of very slow insert is still an issue.

      1. long-run-rc10_benchRun.log.html
        395 kB
        Rui Zhang
      2. mongod-rc10-8col.log.html
        72 kB
        Rui Zhang
      3. mongod-rc8-8col.log.html
        107 kB
        Rui Zhang
      1. flamegraph_batch_insert.png
        169 kB
      2. insert.png
        66 kB

        Issue Links

          Activity

          Hide
          rui.zhang Rui Zhang added a comment -

          long-run-rc10_benchRun.log.html show the slow insert in the first couple minutes.

          Show
          rui.zhang Rui Zhang added a comment - long-run-rc10_benchRun.log.html show the slow insert in the first couple minutes.
          Hide
          fdoray François Doray added a comment - - edited

          Slow inserts (>750 ms) spend most of their time in this call stack:

          [timer]
          select
          __wt_sleep
          __wt_page_in_func (with ref->state = WT_REF_MEM, flags = 0)
          __wt_row_search
          __wt_btcur_insert
          __curfile_insert
          mongo::WiredTigerIndexUnique::_insert(__wt_cursor*, mongo::BSONObj const&, mongo::RecordId const&, bool)
          mongo::WiredTigerIndex::insert(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&, bool)
          mongo::BtreeBasedAccessMethod::insert(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&, mongo::InsertDeleteOptions const&, long*)
          mongo::IndexCatalog::_indexRecord(mongo::OperationContext*, mongo::IndexCatalogEntry*, mongo::BSONObj const&, mongo::RecordId const&)
          mongo::IndexCatalog::indexRecord(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&)
          mongo::Collection::_insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool)
          mongo::Collection::insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool)
          mongo::WriteBatchExecutor::execOneInsert(mongo::WriteBatchExecutor::ExecInsertsState*, mongo::WriteErrorDetail**)
          mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*)
          mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator<mongo::BatchedUpsertDetail*> >*, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*)
          mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*)
          mongo::WriteCmd::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&, bool)
          mongo::_execCommand(mongo::OperationContext*, mongo::Command*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&, bool)
          mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, int, char const*, mongo::BSONObj&, mongo::BSONObjBuilder&, bool)
          mongo::_runCommands(mongo::OperationContext*, char const*, mongo::BSONObj&, mongo::_BufBuilder<mongo::TrivialAllocator>&, mongo::BSONObjBuilder&, bool, int)
          mongo::runQuery(mongo::OperationContext*, mongo::Message&, mongo::QueryMessage&, mongo::NamespaceString const&, mongo::CurOp&, mongo::Message&, bool)
          mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&, bool)
          mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*)
          mongo::PortMessageServer::handleIncomingMsg(void*)
          start_thread

          Manual observations reveal that the __evict_server thread runs for about 0.3ms just before the "query" thread stops its series of timers, so I guess it's that thread that allows the execution to continue. There is almost no CPU/disk usage during the execution of the timers...

          For inserts [500 ms, 750 ms], the main source of contention seems to be disk operations. See attached flame graph. [blockdevice] means that the thread is waiting for a request to the disk to be completed.

          These observations come from an LTTng trace, captured on Ubuntu 14.04.

          Show
          fdoray François Doray added a comment - - edited Slow inserts (>750 ms) spend most of their time in this call stack: [timer] select __wt_sleep __wt_page_in_func (with ref->state = WT_REF_MEM, flags = 0) __wt_row_search __wt_btcur_insert __curfile_insert mongo::WiredTigerIndexUnique::_insert(__wt_cursor*, mongo::BSONObj const&, mongo::RecordId const&, bool) mongo::WiredTigerIndex::insert(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&, bool) mongo::BtreeBasedAccessMethod::insert(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&, mongo::InsertDeleteOptions const&, long*) mongo::IndexCatalog::_indexRecord(mongo::OperationContext*, mongo::IndexCatalogEntry*, mongo::BSONObj const&, mongo::RecordId const&) mongo::IndexCatalog::indexRecord(mongo::OperationContext*, mongo::BSONObj const&, mongo::RecordId const&) mongo::Collection::_insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool) mongo::Collection::insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool) mongo::WriteBatchExecutor::execOneInsert(mongo::WriteBatchExecutor::ExecInsertsState*, mongo::WriteErrorDetail**) mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*) mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator<mongo::BatchedUpsertDetail*> >*, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo::WriteErrorDetail*> >*) mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*) mongo::WriteCmd::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&, bool) mongo::_execCommand(mongo::OperationContext*, mongo::Command*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&, bool) mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, int, char const*, mongo::BSONObj&, mongo::BSONObjBuilder&, bool) mongo::_runCommands(mongo::OperationContext*, char const*, mongo::BSONObj&, mongo::_BufBuilder<mongo::TrivialAllocator>&, mongo::BSONObjBuilder&, bool, int) mongo::runQuery(mongo::OperationContext*, mongo::Message&, mongo::QueryMessage&, mongo::NamespaceString const&, mongo::CurOp&, mongo::Message&, bool) mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&, bool) mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*) mongo::PortMessageServer::handleIncomingMsg(void*) start_thread Manual observations reveal that the __evict_server thread runs for about 0.3ms just before the "query" thread stops its series of timers, so I guess it's that thread that allows the execution to continue. There is almost no CPU/disk usage during the execution of the timers... For inserts [500 ms, 750 ms] , the main source of contention seems to be disk operations. See attached flame graph. [blockdevice] means that the thread is waiting for a request to the disk to be completed. These observations come from an LTTng trace, captured on Ubuntu 14.04.
          Hide
          michael.cahill Michael Cahill added a comment -

          Thanks for the extra information: as mentioned by Darren Wood, this issue will be fixed by https://github.com/wiredtiger/wiredtiger/pull/1706

          Show
          michael.cahill Michael Cahill added a comment - Thanks for the extra information: as mentioned by Darren Wood , this issue will be fixed by https://github.com/wiredtiger/wiredtiger/pull/1706
          Hide
          michael.cahill Michael Cahill added a comment -

          François Doray, can you share details of the LTTng tracing?

          Show
          michael.cahill Michael Cahill added a comment - François Doray , can you share details of the LTTng tracing?

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: