[SERVER-26988] Secondary delay causes large drop in insert rate on the primary due to cache full condition Created: 10/Nov/16  Updated: 02/May/19  Resolved: 02/May/19

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Michael Cahill (Inactive) Assignee: Alex Cameron (Inactive)
Resolution: Done Votes: 2
Labels: neweng, storage-engines
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: PNG File lagging.png     PNG File slave_delay_metrics.png    
Issue Links:
Backports
Related
related to SERVER-23622 Inconsistent throughput during insert... Closed
is related to SERVER-18081 Tailing the oplog requires paging in ... Closed
Operating System: ALL
Sprint: Storage Engines 2019-05-06
Participants:
Case:
Story Points: 5

 Description   

With a heavy insert load and a secondary that is delayed the cache on the primary fills to 100% and operation rates drop. Here's a run showing behavior on the primary with the secondary delayed due to lag, but a similar effect is seen if the secondary is intentionally delayed using slaveDelay.

  • from D-E the cache is 95% full and insert rate drops considerably, possibly due to application threads doing evictions?
  • F-G and H-I seem to be seem to be related to checkpoints, possibly also in combination with the full cache?
  • the rate of pages walked for eviction is generally very high, about 6k times the rate of pages actually evicted, suggesting that the issue is difficulty finding pages to evict to keep the cache at target levels

The high rate of pages walked for eviction suggests a connection to SERVER-22831, which also showed that symptom in connection with a full cache; however the above run was on 3.2.5-rc1 where SERVER-22831 was fixed, so it seems there is a different issue here.

The above test involved

  • 3.2.5-rc1
  • 2-node replica set
  • 25 GB cache
  • 100 GB oplog
  • 5 threads inserting 800 byte documents into 5 separate collections

for t in $(seq 5); do
    mongo --eval "
        x = ''
        for (var i=0; i<800; i++)
            x += 'x'
        docs = []
        for (var i=0; i<1000; i++)
            docs.push({x:x})
        ops = [{
            op: 'insert',
            ns: 'test.c' + '$t',
            doc: docs,
        }]
        res = benchRun({
            ops: ops,
            seconds: 10000,
            parallel: 1
        })
    " &
done
 
wait



 Comments   
Comment by Michael Cahill (Inactive) [ 01/May/19 ]

Thanks alex.cameron, happy for this to be closed.

Comment by Alex Cameron (Inactive) [ 01/May/19 ]

I ran this test with a build of commit hash b877bd0172b613e77365f29886d359e5230f1a3e on my own developer box (had to lower the cache size slightly).

mlaunch start --binarypath . --replicaset --nodes 2 --wiredTigerCacheSizeGB 15 --oplogSize 100000

And then manually set the slave delay such that rs.conf() was returning this:

replset:PRIMARY> rs.conf()
{
        "_id" : "replset",
        "version" : 2,
        "protocolVersion" : NumberLong(1),
        "writeConcernMajorityJournalDefault" : true,
        "members" : [
                {
                        "_id" : 0,
                        "host" : "localhost:27017",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : false,
                        "priority" : 1,
                        "tags" : {
 
                        },
                        "slaveDelay" : NumberLong(0),
                        "votes" : 1
                },
                {
                        "_id" : 1,
                        "host" : "localhost:27018",
                        "arbiterOnly" : false,
                        "buildIndexes" : true,
                        "hidden" : true,
                        "priority" : 0,
                        "tags" : {
 
                        },
                        "slaveDelay" : NumberLong(20),
                        "votes" : 1
                }
        ],
        "settings" : {
                "chainingAllowed" : true,
                "heartbeatIntervalMillis" : 2000,
               "heartbeatTimeoutSecs" : 10,
                "electionTimeoutMillis" : 10000,
                "catchUpTimeoutMillis" : -1,
                "catchUpTakeoverDelayMillis" : 30000,
                "getLastErrorModes" : {
 
                },
                "getLastErrorDefaults" : {
                        "w" : 1,
                        "wtimeout" : 0
                },
                "replicaSetId" : ObjectId("5cc9ab09f67ec0abbb006e0f")
        }
}

The metrics looked like this:

michael.cahill ian.whalen
As you can see, the insert counter doesn't have the same kind of periodic "U" shaped drops.
I believe this is ok to close if you're satisfied with this.

Comment by Ian Whalen (Inactive) [ 02/Feb/18 ]

We believe the issue seen in this workload is resolved - primary work here will probably be to investigate and confirm or reject this fact. If rejecting, please put back into Needs Triage.

Generated at Thu Feb 08 04:13:48 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.