Hey Jim Walker Although the test was on a magma backend - and so not supported in MH. Could you take a look just to ensure that its not uncovering an issue we might hit in MH, with couchstore backend? thanks

Daniel Owen , above test we ran with couchstore as backend to have benchmark numbers with couchstore.

Ah thanks Mahesh Mandhare we will investigate.

With memory used being so high, a number of "safety' systems have kicked in, overall replication has been massively slowed down.

On one node (cbcollect_info_ns_1@172.23.97.39_20190910-055023) we see that it is very slowly supplying DCP from a disk backfill, here we can clearly see that the backfill is being paused due to the lack of memory for it to bring data in from disk.

2019-09-09T22:33:26.328717-07:00 INFO (bucket-1) DCP backfilling task temporarily suspended because the current memory usage is too high

2019-09-09T22:33:27.328810-07:00 INFO (bucket-1) DCP backfilling task temporarily suspended because the current memory usage is too high

2019-09-09T22:33:28.328953-07:00 INFO (bucket-1) DCP backfilling task temporarily suspended because the current memory usage is too high

2019-09-09T22:33:29.329039-07:00 INFO (bucket-1) DCP backfilling task temporarily suspended because the current memory usage is too high

2019-09-09T22:33:30.329078-07:00 INFO (bucket-1) DCP backfilling task temporarily suspended because the current memory usage is too high

We're backfilling because the severe lack of memory has caused DCP to drop cursors

2019-09-09T22:33:21.000737-07:00 INFO (bucket-1) Triggering memory recovery as checkpoint_memory (3783 MB) exceeds cursor_dropping_checkpoint_mem_upper_mark (50%, 3072 MB). Attempting to free 4256 MB of memory.

The same node is also unable to consume items

2019-09-09T22:33:03.743991-07:00 WARNING 323: (bucket-1) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.97.38->ns_1@172.23.97.39:bucket-1 - vb:80 Got error 'no memory' while trying to process mutation with seqno:569034

2019-09-09T22:33:03.789213-07:00 WARNING 323: (bucket-1) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.97.38->ns_1@172.23.97.39:bucket-1 - vb:70 Got error 'no memory' while trying to process mutation with seqno:546229

2019-09-09T22:33:03.848016-07:00 WARNING 323: (bucket-1) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.97.38->ns_1@172.23.97.39:bucket-1 - vb:2 Got error 'no memory' while trying to process mutation with seqno:563000

2019-09-09T22:33:03.854111-07:00 WARNING 323: (bucket-1) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.97.38->ns_1@172.23.97.39:bucket-1 - vb:18 Got error 'no memory' while trying to process mutation with seqno:557148

2019-09-09T22:33:03.918303-07:00 WARNING 323: (bucket-1) DCP (Consumer) eq_dcpq:replication:ns_1@172.23.97.38->ns_1@172.23.97.39:bucket-1 - vb:20 Got error 'no memory' while trying to process mutation with seqno:555992

The other node is similar.

Note replication is possibly progressing, it's happening slowly as the various checks to avoid going above the bucket quota in the system keep pausing and retrying.

E.g. progress looks to be happening e.g. vb:20 logged 'no memory' for seqno:555992, but at the cbcollect time we can see in stats.log that vb:20 is now at 556321

Jim Walker ,

We see that "ep_dcp_replica_items_remaining" stuck at 19,360 from 2019-09-09T22:33:29 till we aborted run at 2019-09-10T02:42:02.

We print this stat on console of job- http://perf.jenkins.couchbase.com/job/magma-hidd/441/consoleFull 

Node .39 is definietly a problem...

The backfill task is perpetually being put to sleep because memory is too high (above quota), so this is one reason DCP appears to be paused, on that same node checkpoints seem to be consuming a lot of resources

e.g. vb0 which is replica and only has the persistence cursor (similar for many others, the checkpoint can be seen to consume a lot of memory).

 vb_0:last_closed_checkpoint_id:                                                                11

 vb_0:mem_usage:                                                                                32701361

 vb_0:num_checkpoint_items:                                                                     364300

 vb_0:num_checkpoints:                                                                          1

 vb_0:num_conn_cursors:                                                                         1

 vb_0:num_items_for_persistence:                                                                0

 vb_0:num_open_checkpoint_items:                                                                364299

 vb_0:open_checkpoint_id:                                                                       12

 vb_0:persisted_checkpoint_id:                                                                  11

 vb_0:persistence:cursor_checkpoint_id:                                                         12

 vb_0:persistence:cursor_seqno:                                                                 566706

 vb_0:persistence:num_visits:                                                                   308

 vb_0:state:                                                                                    replica

Suspect this is could be cause by an issue fixed by https://issues.couchbase.com/browse/MB-35812 http://review.couchbase.org/#/c/114376/ where checkpoint memory isn't being freed.

This was committed into build 6.5.0-4244

Retry on latest build

Mahesh Mandhare it would be good to re-run on a later build (as per prior comment), some further digging shows that the expel fix I linked to may not be the fix as checkpoint overhead is quite high, further changes are needed for checkpoint overhead reduction (during expelling) - so re-opening to track

Build 6.5.0-4282

Tried same test on build 6.5.0-4282 and seeing the same issue again. Replication stuck at 24,040 from 2019-09-17T03:08:19 till we abort job at 2019-09-17T08:57:27

Job- http://perf.jenkins.couchbase.com/job/magma-hidd/458/

Logs-
https://cb-jira.s3.us-east-2.amazonaws.com/logs/replication_stuck/collectinfo-2019-09-17T155416-ns_1%40172.23.97.38.zip
https://cb-jira.s3.us-east-2.amazonaws.com/logs/replication_stuck/collectinfo-2019-09-17T155416-ns_1%40172.23.97.39.zip

A toy-build passed

http://perf.jenkins.couchbase.com/job/magma-hidd/463/console

Some more work to tidy up the mem overhead accounting, split patch into 2 parts. Nearly done...

Build couchbase-server-6.5.0-4357 contains kv_engine commit 0446ad5 with commit message:
MB-35889: Use tracking allocator for Checkpoint memOverhead tracking

Build couchbase-server-6.5.0-4386 contains kv_engine commit 581e575 with commit message:
MB-35889: Purge Checkpoint key indexes during expel and state change

Build couchbase-server-6.5.0-4415 contains kv_engine commit 22b6ac3 with commit message:
MB-35889: Tune the dcp cursor dropping tests

Build 6.5.0-4415

Verified that now replication does not stuck for same test.

Job- http://perf.jenkins.couchbase.com/job/magma-hidd/482

Latest logs node

• .38 has dcp stuck at 19k, memory however seems. mem_used is below the low water mark, not that ~50% of memory does appear to be ep_overhead
• .39 is not looking good though with mem_used way over high_water and close to max size

.38 is stuck because .39 is not processing DCP input and flow-control has stoppped the flow of replication

This issue is likely to be back because MB-36261 has had to revert part of the original fix made in this MB.

To improve this issue it's going to need much more work on checkpoints, specifically the Checkpoint::keyIndex, but that will have an impact on sync-replication.

For now will defer this to cheshire-cat where we will be able to address such low RR situations and make such changes once we've gained more confidence in sync-replication (and can do more work on the keyIndex)

Build couchbase-server-6.5.0-4546 contains kv_engine commit 380547e with commit message:
MB-36301: Partial Revert "MB-35889: Purge Checkpoint key indexes during expel and state change"

Build couchbase-server-7.0.0-1009 contains kv_engine commit 380547e with commit message:
MB-36301: Partial Revert "MB-35889: Purge Checkpoint key indexes during expel and state change"

Build couchbase-server-6.5.0-4583 contains kv_engine commit 2d04589 with commit message:
MB-36301: Revert "MB-35889: Use tracking allocator for Checkpoint memOverhead tracking"

Build couchbase-server-7.0.0-1013 contains kv_engine commit 2d04589 with commit message:
MB-36301: Revert "MB-35889: Use tracking allocator for Checkpoint memOverhead tracking"

Status of this ticket

We now track checkpoint memory in a better way, but we are not erasing items from the keyIndex (checkpoint overhead) due to sync write issues (MB-36261).

Things to do

• Drop the keyIndex when we close a checkpoint - MB-35970. This was done as part of this ticket but was reverted. We can probably revisit doing this.
• Investigate usage of the keyIndex for replicas. This can grow O( n) which is problematic when we have disk checkpoints. I believe the only current usage is sync write based sanity checks. Perhaps we could erase non sync write items from this or simplify it on replicas to use less memory.

It looks like it is fine to allow the expelling code to erase mutations from the committed key indexes of Disk checkpoints on replicas as we only ever send/receive mutations (not commits) as part of Disk snapshots. For a Disk checkpoints everything should be fine provided we only receive each key once. Level of confidence on this is very high for couchstore, but we don't yet have the bake time to have the same level of confidence in magma. The only issue we would (and this is the case currently too) see if we did have multiple mutations for the same key in a Disk snapshot on the replica would be incorrect stats accounting. If we had multiple prepares of the same key then we would throw an exception.

We could consider allowing the replica to expel mutations from Memory checkpoints too, but this would result in stats being wrong whenever we de-dupe in the checkpoint manager on the replica. Should look more into what we can do with the stats to allow us to do this for Memory checkpoints, but the value in doing so is much less than for DIsk checkpoints.

Daniel Owen / Dave Finlay / Shivani Gupta Proposing this for 6.6.0 - I believe the work required is small - just fixing some unforeseen issues in the previous 6.5.0 version of the patch. This would fix issues observed at customers where rebalance can hang and result in unavailability of replicas / unable to perform cluster maintenance.

For this change I'd propose that we only do the following:

• Investigate usage of the keyIndex for replicas. This can grow O( n) which is problematic when we have disk checkpoints. I believe the only current usage is dedupe / sync write based sanity checks. We can simply not add keys to Disk checkpoints to avoid this issue.

It would be nice to also drop key indexes when closing checkpoints (MB-35970), but this created a regression the last time we did it (MB-36301). We can probably do this with a bit more work, but I think that's more reasonable for Cheshire-Cat than 6.6.0.

Build couchbase-server-6.6.0-7646 contains kv_engine commit 2bd86cd with commit message:
MB-35889: Don't add keys to Checkpoint indexes for Disk checkpoints

Jepsen tests caught a crash with this, need to loosen up some assertions and add a test or two - MB-39435.

Build couchbase-server-6.6.0-7654 contains kv_engine commit 7579822 with commit message:
MB-35889: Don't invalidate index entry for Disk checkpoint for expel

Build couchbase-server-7.0.0-2130 contains kv_engine commit 7579822 with commit message:
MB-35889: Don't invalidate index entry for Disk checkpoint for expel

Build couchbase-server-7.0.0-2130 contains kv_engine commit 2bd86cd with commit message:
MB-35889: Don't add keys to Checkpoint indexes for Disk checkpoints

I do a run on build 6.6.0-7883. In this run, ep_dcp_replica_items_remaining is able to reach 0. I close this ticket.

http://perf.jenkins.couchbase.com/job/rhea-5node1/120/

2020-07-21T13:43:40 [INFO] Monitoring DCP queues: bucket-1

2020-07-21T13:43:40 [INFO] ep_dcp_replica_items_remaining reached 0

2020-07-21T13:43:40 [INFO] ep_dcp_other_items_remaining reached 0

2020-07-21T13:43:40 [INFO] Monitoring replica count match: bucket-1

2020-07-21T13:43:40 [INFO] curr_items: 250000000, replica_curr_items: 250000000