[SERVER-21008] 20% Single thread performance regression on Insert.EmptyCapped and Insert.CappedSeqIntID on wiredTiger Created: 08/Oct/15  Updated: 01/Apr/16  Resolved: 30/Oct/15

Status: Closed
Project: Core Server
Component/s: Performance, WiredTiger
Affects Version/s: None
Fix Version/s: 3.2.0-rc2

Type: Bug Priority: Major - P3
Reporter: David Daly Assignee: Martin Bligh
Resolution: Done Votes: 0
Labels: mpreg
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:
Linked BF Score: 0

 Description   

20% regression in single thread performance compared to baseline. This is using a recent compare to 3.1.7.

To recreate the empty capped in the shell:

var setup = function( collection ) {
                  collection.drop();
                  collection.runCommand( "create", { capped : true,
                                                     size : 32 * 1024 } );
}              
use test0
setup(db.Insert_EmptyCapped0)
benchRun({"ops":[{"op":"insert","doc":{},"ns":"test0.Insert_EmptyCapped0","safe":false,"w":0,"j":false,"writeCmd":true}],"seconds":30,"host":"127.0.0.1:27017","parallel":1})

Original failure message:

[2015/10/08 12:10:34.838] Override in references for test Insert.EmptyCapped.SeqIntID
[2015/10/08 12:10:34.838] regression found on 1: drop from 12386.47 ops/sec (commit 7d7f4) to 9807.34 ops/sec for comparison Baseline Comparison 3.0.6-Baseline. Diff is 2579.13 ops/sec (20.82%), noise level is 91.96 ops/sec and multiple is 2.00
[2015/10/08 12:10:34.838] regression found on 2: drop from 25065.53 ops/sec (commit 7d7f4) to 20346.30 ops/sec for comparison Baseline Comparison 3.0.6-Baseline. Diff is 4719.23 ops/sec (18.83%), noise level is 234.05 ops/sec and multiple is 2.00

[2015/10/08 12:10:34.839] Override in references for test Insert.EmptyCapped
[2015/10/08 12:10:34.839] regression found on 1: drop from 12445.05 ops/sec (commit 7d7f4) to 9495.62 ops/sec for comparison Baseline Comparison 3.0.6-Baseline. Diff is 2949.43 ops/sec (23.70%), noise level is 154.85 ops/sec and multiple is 2.00
[2015/10/08 12:10:34.839] regression found on 2: drop from 25188.91 ops/sec (commit 7d7f4) to 20805.12 ops/sec for comparison Baseline Comparison 3.0.6-Baseline. Diff is 4383.79 ops/sec (17.40%), noise level is 400.21 ops/sec and multiple is 2.00



 Comments   
Comment by Githook User [ 30/Oct/15 ]

Author:

{u'username': u'martinbligh', u'name': u'Martin Bligh', u'email': u'mbligh@mongodb.com'}

Message: SERVER-21008: Add missing part of patch "Fixed cappedDelete to keep track of beginning of collection so it skips tombstones"
Branch: master
https://github.com/mongodb/mongo/commit/aa2c2ac32a50f746c8854fdeb3719623853affa4

Comment by Githook User [ 29/Oct/15 ]

Author:

{u'username': u'martinbligh', u'name': u'Martin Bligh', u'email': u'mbligh@mongodb.com'}

Message: SERVER-21008: Fixed cappedDelete to keep track of beginning of collection so it skips tombstones
Branch: master
https://github.com/mongodb/mongo/commit/a4b34582b6fd71785f8be653409293788476f03f

Comment by Githook User [ 29/Oct/15 ]

Author:

{u'username': u'martinbligh', u'name': u'Martin Bligh', u'email': u'mbligh@mongodb.com'}

Message: Revert "SERVER-21008: Fixed cappedDelete to keep track of beginning of collection so it skips tombstones"

This reverts commit 9d7413280fb706e037082ea84442bb83579df58c.
Branch: master
https://github.com/mongodb/mongo/commit/633b0d140e5142772df273244567ee81e6cb428d

Comment by Githook User [ 29/Oct/15 ]

Author:

{u'username': u'martinbligh', u'name': u'Martin Bligh', u'email': u'mbligh@mongodb.com'}

Message: SERVER-21008: Fixed cappedDelete to keep track of beginning of collection so it skips tombstones
Branch: master
https://github.com/mongodb/mongo/commit/9d7413280fb706e037082ea84442bb83579df58c

Comment by Ramon Fernandez Marina [ 26/Oct/15 ]

Githook message for commit to this ticket:

Author:{u'username': u'ksuarz', u'name': u'Kyle Suarez', u'email': u'ksuarz@gmail.com'}
Message: SERVER-21008 overrides for WT inserts
 
Overrides Insert.EmptyCapped* for the linux_wt_standalone and linux_wt_repl.
 
Closes #1039
 
Signed-off-by: David Daly <david.daly@mongodb.com>
Branch: master
https://github.com/mongodb/mongo/commit/75689917412c571427f12b7fe29a4dfa458d2df3

Comment by Martin Bligh [ 19/Oct/15 ]

Forward porting that change fixed the caller list but doesn't seem to have improved perf at all:

-  32.05%  mongod  mongod               [.] __wt_btcur_next                                                                                      
   - __wt_btcur_next                                                                                                                             
      - 99.92% __curfile_next                                                                                                                    
         - 54.15% mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock(mongo::OperationContext*, mongo::RecordId const&)                    
              mongo::WiredTigerRecordStore::cappedDeleteAsNeeded(mongo::OperationContext*, mongo::RecordId const&)                               
              mongo::WiredTigerRecordStore::insertRecords(mongo::OperationContext*, std::vector<mongo::Record, std::allocator<mongo::Record> >*, 
              mongo::Collection::_insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSON
              mongo::Collection::insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSONO
              mongo::Collection::insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool, bool)                                     
              mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mo
              mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator
              mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*)                       
              mongo::WriteCmd::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&)     
              mongo::Command::run(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)             
              mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilde
              mongo::runCommands(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)              
              mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&)                  
              mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*)                                                   
              mongo::PortMessageServer::handleIncomingMsg(void*)                                                                                 
              start_thread                                                                                                                       
         - 45.85% __session_truncate                                                                                                             
              mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock(mongo::OperationContext*, mongo::RecordId const&)                        
              mongo::WiredTigerRecordStore::cappedDeleteAsNeeded(mongo::OperationContext*, mongo::RecordId const&)                               
              mongo::WiredTigerRecordStore::insertRecords(mongo::OperationContext*, std::vector<mongo::Record, std::allocator<mongo::Record> >*, 
              mongo::Collection::_insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSON
              mongo::Collection::insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSONO
              mongo::Collection::insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool, bool)                                     
              mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mo
              mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator
              mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*)                       
              mongo::WriteCmd::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&)     
              mongo::Command::run(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)             
              mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilde
              mongo::runCommands(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)              
              mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&)                  
              mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*)                                                   
              mongo::PortMessageServer::handleIncomingMsg(void*)                                                                                 
              start_thread                                                                                                                       
+   1.43%  mongod  mongod               [.] __wt_row_search                                                                                      
+   1.24%  mongod  mongod               [.] operator new(unsigned long) 

Comment by Martin Bligh [ 19/Oct/15 ]

Most obvious difference seems to be a lot more time spent in __wt_btcur_next.
Not convinced calltree for 3.0.6 is correct

3.0.6

-  12.67%  mongod  mongod               [.] __wt_btcur_next                                        
   - __wt_btcur_next                                                                               
   - __curfile_next                                                                                
        56.18% mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock(mongo::OperationContext*, 
      - 43.82% __session_truncate                                                                  
           mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock(mongo::OperationContext*, mong

3.2.0-rc0

-  33.51%  mongod  mongod               [.] __wt_btcur_next                                                                                      
   - __wt_btcur_next                                                                                                                             
      - 99.91% __curfile_next                                                                                                                    
           mongo::WiredTigerRecordStore::cappedDeleteAsNeeded_inlock(mongo::OperationContext*, mongo::RecordId const&)                           
           mongo::WiredTigerRecordStore::cappedDeleteAsNeeded(mongo::OperationContext*, mongo::RecordId const&)                                  
           mongo::WiredTigerRecordStore::insertRecords(mongo::OperationContext*, std::vector<mongo::Record, std::allocator<mongo::Record> >*, boo
           mongo::Collection::_insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSONObj
           mongo::Collection::insertDocuments(mongo::OperationContext*, __gnu_cxx::__normal_iterator<mongo::BSONObj*, std::vector<mongo::BSONObj,
           mongo::Collection::insertDocument(mongo::OperationContext*, mongo::BSONObj const&, bool, bool)                                        
           mongo::WriteBatchExecutor::execInserts(mongo::BatchedCommandRequest const&, std::vector<mongo::WriteErrorDetail*, std::allocator<mongo
           mongo::WriteBatchExecutor::bulkExecute(mongo::BatchedCommandRequest const&, std::vector<mongo::BatchedUpsertDetail*, std::allocator<mo
           mongo::WriteBatchExecutor::executeBatch(mongo::BatchedCommandRequest const&, mongo::BatchedCommandResponse*)                          
           mongo::WriteCmd::run(mongo::OperationContext*, std::string const&, mongo::BSONObj&, int, std::string&, mongo::BSONObjBuilder&)        
           mongo::Command::run(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)                
           mongo::Command::execCommand(mongo::OperationContext*, mongo::Command*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderIn
           mongo::runCommands(mongo::OperationContext*, mongo::rpc::RequestInterface const&, mongo::rpc::ReplyBuilderInterface*)                 
           mongo::assembleResponse(mongo::OperationContext*, mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&)                     
           mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*)                                                      
           mongo::PortMessageServer::handleIncomingMsg(void*)                                                                                    
           start_thread                                                                                                                          

Comment by David Daly [ 16/Oct/15 ]

Link to result page comparing to 3.1.7. Should be in the graph view. Look at the 1 and 2 thread bars.

Comment by David Daly [ 16/Oct/15 ]

The issue doesn't show up with 8 threads. It only fails at 1 and 2 threads, but is 20% for those cases.

Comment by Martin Bligh [ 15/Oct/15 ]

Tried rerunning Insert.EmptyCapped locally w/8 threads & 30 s elapsed.

3.0.6
8 55618.62898167136
8 53403.41060717645
8 54475.529174778814

master
8 56242.39828742325
8 56025.6206797944
8 55867.306293627975

So if anything it seems faster.

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