[SERVER-20996] 74% performance regression in db.c.remove() Created: 18/Oct/15  Updated: 30/Mar/16  Resolved: 19/Nov/15

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

Type: Bug Priority: Major - P3
Reporter: Bruce Lucas (Inactive) Assignee: David Hows
Resolution: Done Votes: 0
Labels: WTplaybook
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File 3.2.0-rc0-2.4M.png    
Issue Links:
Related
related to SERVER-20876 Hang in scenario with sharded ttl col... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

74% performance regression in db.c.remove()

Test inserts n empty documents into a collection, then removes them with db.c.remove({}). Timing:

documents:     240 k    2.4 M     
3.0.7           3.4 s    36.0 s    
3.2.0-rc0      10.7 s   138.1 s   
regression     68%      74%      

The rate of document removals under 3.2.0-rc0 is initially lower and also declines over time (shown below), whereas under 3.0.7 it started higher and remained constant.

I observed on a longer run that the rate of removal continued to decline, so would expect the size of the regression to increase with a larger number of documents, continuing the trend seen with the two collection sizes measured above.

Stack traces show significant time spent walking the tree, so perhaps this is related to this issue.

Repro script:

db=/ssd/db
 
function start {
    killall -9 -w mongod
    rm -rf $db
    mkdir -p $db/r0
    mongod --storageEngine wiredTiger --dbpath $db/r0 --logpath $db/mongod.log --fork
    sleep 2
}
 
function insert {
    threads=24
    for t in $(seq $threads); do
        mongo --eval "
            count = 100000
            every = 10000
            for (var i=0; i<count; ) {
                var bulk = db.c.initializeUnorderedBulkOp();
                for (var j=0; j<every; j++, i++)
                    bulk.insert({})
                bulk.execute();
                print(i)
            }
        " &
    done
    wait
}
 
function remove {
 
    mongo --eval "
        t = new Date()
        db.c.remove({})
        t = new Date() - t
        print(t/1000.0)
    "
}
 
start; insert; remove



 Comments   
Comment by Githook User [ 19/Nov/15 ]

Author:

{u'username': u'daveh86', u'name': u'David Hows', u'email': u'howsdav@gmail.com'}

Message: SERVER-20996 - Avoid advancing cursors multiple times
Branch: master
https://github.com/mongodb/mongo/commit/864111bec7bc9b764e9c9d4c2a0bcd5c2e417dd3

Comment by David Hows [ 17/Nov/15 ]

Just finished the bisect of the second part of the regressions from 50 sec to 100 sec.

Looks like the following drop from WT into Mongo was the cause. This drop also includes a pull from wt develop into the wt mongodb-3.2 branch, so lots of threads to pull apart.

881f00984ce2692b81154d5ea3d5fb589b484c70 is the first bad commit
commit 881f00984ce2692b81154d5ea3d5fb589b484c70
Author: Michael Cahill <michael.cahill@mongodb.com>
Date:   Fri Sep 18 17:17:34 2015 +1000
 
    Import wiredtiger-wiredtiger-2.6.1-1119-g16e3e48.tar.gz from wiredtiger branch mongodb-3.2
 
:040000 040000 ef85284e1eaa02795de5b86b14c3a400005b298a b39c443a336456aadb3021522456291a57d8e1bb M	src

Comment by Alexander Gorrod [ 17/Nov/15 ]

david.hows could you re-run your test removing a varied proportion of the content? i.e: 5%, 15%, 25%, ...95%. It would be interesting to know whether the volume of removes is relevant.

Comment by David Hows [ 17/Nov/15 ]

As per a suggestion from Michael, I have made a second workload that looks to remove 5% of documents from the collection randomly.

In 3.0.7 we get

MongoDB shell version: 3.0.7
connecting to: test
2.184

In 3.2.0 we get

MongoDB shell version: 3.2.0-rc2-206-g7790034
connecting to: test
1.942

So, this looks like randomised removes themselves aren't a problem and its only the full remove of all documents that is in issue here.

Comment by David Hows [ 17/Nov/15 ]

According to a git bisection, the first half of this regression (between 3.1.4 and 3.1.5) was introduced by SERVER-16444.

3b731debe162706cbbfabd9578bbb57ab5a7a7d8 is the first bad commit
commit 3b731debe162706cbbfabd9578bbb57ab5a7a7d8
Author: Mathias Stearn <mathias@10gen.com>
Date:   Mon May 18 18:01:38 2015 -0400
 
    SERVER-16444 New API for navigating RecordStores
 
:040000 040000 033837fe4d42e5969f603702631f35ebdf485bb0 d2d80e5980690f45b8719a8f90d37520418b054f M	jstests
:040000 040000 2fcbfefc0e1aa15444dc2b7d207012f61ec0fd85 fd6ceba1677b82dda7a9404a9e52830a453aa9f0 M	src

I will chase down the other half now.

Comment by David Hows [ 16/Nov/15 ]

You were right on WT-2182

MongoDB shell version: 3.2.0-rc2-206-g7790034
connecting to: test
83.563

__wt_split_reverse was even worse again

MongoDB shell version: 3.2.0-rc2-206-g7790034
connecting to: test
98.452

I wasn't able to trivially make the changes to __wt_page_evict_soon that didn't freeze MongoD.

I've also run against 3.1.5 just to see what the impact was only a 5x regression. Seems like there may be more than one thing at play here.

MongoDB shell version: 3.1.5
connecting to: test
53.285

Final testing shows 3.1.4 looks like this, so I suspect that the regression may have started in 3.1.4

MongoDB shell version: 3.1.4
connecting to: test
13.848

Comment by Michael Cahill (Inactive) [ 16/Nov/15 ]

daveh86, can you please try a few things?

The branch for WT-2182 is worth a try just because it builds better trees, but I don't know of anything in there that specifically helps with remove throughput.

A big change was SERVER-21027, can you please try turning off the call to __wt_page_evict_soon in __wt_btcur_next and __wt_btcur_prev to see whether the code to aggressively clean up tombstones is responsible?

Similarly, try turning off the call to __wt_split_reverse in __evict_delete_ref to see whether that is involved. Thanks!

Comment by David Hows [ 16/Nov/15 ]

Looks like it relates to the MongoD binary, rather than the shell.
3.0.7 shell w/ 3.2 mongod

MongoDB shell version: 3.0.7
connecting to: test
81.021

3.2 shell w/ 3.0.7 mongod

MongoDB shell version: 3.2.0-rc2-206-g7790034
connecting to: test
Cannot use 'commands' readMode, degrading to 'legacy' mode
11.389

Comment by Daniel Pasette (Inactive) [ 16/Nov/15 ]

Can you double check it's not a shell diff? Unlikely, but should verify.

Comment by David Hows [ 16/Nov/15 ]

michael.cahill still looks like there is a pretty big regression.

80~ seconds for RC2 vs 10~ seconds for 3.0.7

MongoDB shell version: 3.2.0-rc2-206-g7790034
connecting to: test
82.492

MongoDB shell version: 3.0.7
connecting to: test
11.474

Comment by Michael Cahill (Inactive) [ 12/Nov/15 ]

daveh86, can you please retest with the tip of master, now that SERVER-21027 is merged?

Comment by Daniel Pasette (Inactive) [ 19/Oct/15 ]

Ran the repro on a series of 3.1 dev series + 3.0.7:

MongoDB shell version: 3.2.0-rc1-pre-
MongoDB server version: 3.0.7
29.807

MongoDB shell version: 3.2.0-rc1-pre-
MongoDB server version: 3.1.6-pre- (49e779d4588fd4d3f50f1da65220875820a68ee2)
100.254

MongoDB shell version: 3.2.0-rc1-pre-
MongoDB server version: 3.1.8
82.795

MongoDB shell version: 3.2.0-rc1-pre-
MongoDB server version: 3.1.9
124.774

MongoDB shell version: 3.2.0-rc1-pre-
MongoDB server version: 3.2.0-rc1-pre-
124.936

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