[SERVER-17382] rc10/wiredTiger multi collection/DB bulk insert slow than rc8 in initial insertion phase Created: 25/Feb/15  Updated: 24/Apr/15  Resolved: 27/Mar/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.0.0-rc10
Fix Version/s: 3.0.2, 3.1.1

Type: Bug Priority: Critical - P2
Reporter: Rui Zhang (Inactive) Assignee: David Hows
Resolution: Done Votes: 0
Labels: 28qa, cap-ss
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File flamegraph_batch_insert.png     PNG File insert.png     HTML File long-run-rc10_benchRun.log.html     HTML File mongod-rc10-8col.log.html     HTML File mongod-rc8-8col.log.html    
Issue Links:
Depends
is depended on by WT-1901 Issues resolved in WiredTiger 2.5.3 Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Completed:
Participants:

 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.



 Comments   
Comment by Michael Cahill (Inactive) [ 02/Mar/15 ]

fdoray, can you share details of the LTTng tracing?

Comment by Michael Cahill (Inactive) [ 02/Mar/15 ]

Thanks for the extra information: as mentioned by darren.wood@10gen.com, this issue will be fixed by https://github.com/wiredtiger/wiredtiger/pull/1706

Comment by François Doray [ 02/Mar/15 ]

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.

Comment by Rui Zhang (Inactive) [ 25/Feb/15 ]

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

Generated at Thu Feb 08 03:44:14 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.