[SERVER-21585] Cache usage exceeds configured value, operations stall, WiredTigerLAS.wt grows - MongoDB

Details

Type: Bug
Status: Closed
Priority: Major - P3
Resolution: Fixed
Affects Version/s: 3.2.0-rc3
Fix Version/s: 3.2.0-rc4
Component/s: WiredTiger
Labels:
None

Backwards Compatibility:
Fully Compatible
Operating System:
ALL

Description

Multiple tests are seeing a cluster of apparently related symptoms:

During the last portion of a checkpoint cache usage grows to well above the configured maximum
Operations stall, probably as a result of cache exceeding maximum
The WiredTigerLAS.wt file grows without bound, and circumstantial evidence related to the use of the WT lookaside cache connects this with the previous two symptoms.
FTDC data capture stalls

Three examples from two different apps:

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Download All

Attachments

update_repro.js

Nov 23 2015 02:39:20 AM +00:00

1 kB

Dan Pasette

ex1.png

188 kB

Nov 20 2015 01:13:59 PM +00:00
ex2.png

199 kB

Nov 20 2015 01:13:59 PM +00:00
ex3.png

195 kB

Nov 20 2015 01:14:19 PM +00:00
oplog-stalls.png

161 kB

Nov 21 2015 02:32:06 PM +00:00
stalls.png

175 kB

Nov 23 2015 09:13:23 PM +00:00
update_repro.png

154 kB

Nov 23 2015 01:51:42 PM +00:00

Issue Links

is depended on by

WT-1973 MongoDB changes for WiredTiger 2.7.0

Resolved

is related to

SERVER-21652 Stalls during checkpoints

Closed

Activity

Comments

Ascending order - Click to sort in descending order

Hide

Permalink

Max Hirschhorn added a comment - Nov 20 2015 08:43:42 PM +00:00 - edited

I was able to reproduce this issue by running the following script. Note that it is the same as repro_server21553.js with a 50GB oplog instead of a 5GB oplog.

12 cores, 24 CPUs, 32GB memory
1-member replica set
oplog size 50 GB, default cache
data on SSD, running without a journal
5 threads inserting 1KB random docs as fast as possible
recent nightly build

Steps to reproduce:

Run the following JavaScript in a mongo shell started with --nodb.
Copy the test to a file repro.js and execute using ./mongo --nodb repro.js

(function() {

    'use strict';

    Random.setRandomSeed();

    var replSetName = 'server21553';

    var rst = new ReplSetTest({

        name: replSetName,

        nodes: 1,

        oplogSize: 50 * 1024,

        nodeOptions: {nojournal: ''}

});

    var nodes = rst.startSet();

    rst.initiate();

    nodes[0].setLogLevel(1, 'storage');

    var docs = [];

    for (var i = 0; i < 1000; i++) {

        var x = '';

        while (x.length < 1000) {

            x += Random.rand();

        docs.push({x: x});

    var ops = [{

        op: 'insert',

        ns: 'test.c',

        doc: docs,

        safe: true,

}];

    var res = benchRun({

        host: nodes[0].host,

        ops: ops,

        seconds: 10000,

        parallel: 5

});

    printjson(res);

    rst.stopSet();

})();

db version v3.2.0-rc3-88-gd2b49fe

git version: d2b49fe116b8d8012220fbbe0419fd2f57265054

Show

Max Hirschhorn added a comment - Nov 20 2015 08:43:42 PM +00:00 - edited I was able to reproduce this issue by running the following script. Note that it is the same as repro_server21553.js with a 50GB oplog instead of a 5GB oplog. 12 cores, 24 CPUs, 32GB memory 1-member replica set oplog size 50 GB, default cache data on SSD, running without a journal 5 threads inserting 1KB random docs as fast as possible recent nightly build Steps to reproduce: Run the following JavaScript in a mongo shell started with --nodb . Copy the test to a file repro.js and execute using ./mongo --nodb repro.js ( function () { 'use strict' ; Random.setRandomSeed(); var replSetName = 'server21553' ; var rst = new ReplSetTest({ name: replSetName, nodes: 1, oplogSize: 50 * 1024, nodeOptions: {nojournal: '' } }); var nodes = rst.startSet(); rst.initiate(); nodes[0].setLogLevel(1, 'storage' ); var docs = []; for ( var i = 0; i < 1000; i++) { var x = '' ; while (x.length < 1000) { x += Random.rand(); } docs.push({x: x}); } var ops = [{ op: 'insert' , ns: 'test.c' , doc: docs, safe: true , }]; var res = benchRun({ host: nodes[0].host, ops: ops, seconds: 10000, parallel: 5 }); printjson(res); rst.stopSet(); })(); db version v3.2.0-rc3-88-gd2b49fe git version: d2b49fe116b8d8012220fbbe0419fd2f57265054

13 older comments

Hide

Permalink

Githook User added a comment - Nov 23 2015 06:10:28 PM +00:00

Author:

{u'name': u'Ramon Fernandez', u'email': u'ramon@mongodb.com'}

Message: Import wiredtiger-wiredtiger-mongodb-3.2.0-rc3-199-g4d72349.tar.gz from wiredtiger branch mongodb-3.2

ref: 4898aa4..4d72349

2cf57a6 ~~SERVER-21585~~ Don't use the lookaside file until the cache is stuck full.
4ad8df7 ~~SERVER-21585~~ Clean up LAS based on the current count of inserted records
Branch: master
https://github.com/mongodb/mongo/commit/e3cd63fcae3deb1140941a51c85564f098062a23

Show

Githook User added a comment - Nov 23 2015 06:10:28 PM +00:00 Author: {u'name': u'Ramon Fernandez', u'email': u'ramon@mongodb.com'} Message: Import wiredtiger-wiredtiger-mongodb-3.2.0-rc3-199-g4d72349.tar.gz from wiredtiger branch mongodb-3.2 ref: 4898aa4..4d72349 2cf57a6 SERVER-21585 Don't use the lookaside file until the cache is stuck full. 4ad8df7 SERVER-21585 Clean up LAS based on the current count of inserted records Branch: master https://github.com/mongodb/mongo/commit/e3cd63fcae3deb1140941a51c85564f098062a23

Hide

Permalink

Ramon Fernandez added a comment - Nov 23 2015 06:13:29 PM +00:00

Using update_repro.js and Keith's changes the WiredTigerLAS.wt file has grown to 28MB after 1h and it's holding steady, so I've merged these changes into the mongo tree.

Show

Ramon Fernandez added a comment - Nov 23 2015 06:13:29 PM +00:00 Using update_repro.js and Keith's changes the WiredTigerLAS.wt file has grown to 28MB after 1h and it's holding steady, so I've merged these changes into the mongo tree.

Hide

Permalink

Bruce Lucas added a comment - Nov 23 2015 09:16:33 PM +00:00

Running with the patch build with an insert-only repro of the issue, it appears that the unbounded growth of the LAS file and of the cache are no longer occurring, although we are still seeing significant stalls of zero throughput associated with checkpoints, up to 30s in this test.

I believe this is a regression relative to 3.0. Should we continue that on this ticket, or spin off a separate ticket?

Show

Bruce Lucas added a comment - Nov 23 2015 09:16:33 PM +00:00 Running with the patch build with an insert-only repro of the issue, it appears that the unbounded growth of the LAS file and of the cache are no longer occurring, although we are still seeing significant stalls of zero throughput associated with checkpoints, up to 30s in this test. I believe this is a regression relative to 3.0. Should we continue that on this ticket, or spin off a separate ticket?

Hide

Permalink

Dan Pasette added a comment - Nov 23 2015 09:26:35 PM +00:00

Bruce, let's spin it off.

Show

Dan Pasette added a comment - Nov 23 2015 09:26:35 PM +00:00 Bruce, let's spin it off.

Hide

Permalink

Bruce Lucas added a comment - Nov 24 2015 01:45:36 PM +00:00

Spun off ~~SERVER-21652~~.

Show

Bruce Lucas added a comment - Nov 24 2015 01:45:36 PM +00:00 Spun off SERVER-21652 .

People

Assignee:

Keith Bostic

Reporter:

Bruce Lucas

Participants:

Bruce Lucas, Dan Pasette, Githook User, Keith Bostic, Max Hirschhorn, Ramon Fernandez

Votes:

0 Vote for this issue

Watchers:

16 Start watching this issue

Dates

Created:

Nov 20 2015 01:13:59 PM +00:00

Updated:

Dec 22 2015 09:11:34 AM +00:00

Resolved:

Nov 24 2015 04:48:19 PM +00:00

Agile

View on Board