[MB-45320] [Magma] Backup performance tests failed on 7.0.0-4797 - Couchbase database

Bo-Chun Wang created issue - 29/Mar/21 2:00 PM

Bo-Chun Wang made changes - 29/Mar/21 2:05 PM

Field	Original Value	New Value
Attachment		Screen Shot 2021-03-29 at 2.04.14 PM.png [ 133132 ]

Bo-Chun Wang made changes - 29/Mar/21 2:07 PM

Description

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{quote}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host http://172.23.97.26 --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{quote}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

*1. backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host http://172.23.105.72 --username Administrator --password password --threads 16 --storage sqlite

Warning: --host is deprecated, use -c/–cluster

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt

2. *Backup failed at the beginning*: During my investigation, my runs hit another issue. I check other backup performance runs and saw they failed because of the same issue. Please find output below. The log file of this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115941.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host http://172.23.105.72 --username Administrator --password password --threads 16 --storage sqlite

Warning: --host is deprecated, use -c/--cluster

Backing up to '2021-03-29T11_57_52.872118914-07_00'

Transferring key value data for bucket 'bucket-1' at 0B/s (about 1h59m42s remaining) 0 items / 0B

[== ] 1.06%

Error backing up cluster: operation has timed out

| Transfer

| --------

| Status | Avg Transfer Rate | Started At | Finished At | Duration |

| Failed | 0B | Mon, 29 Mar 2021 11:57:52 -0700/s | Mon, 29 Mar 2021 11:59:10 -0700 | 1m17s |

| Bucket

| ------

| Name | Status | Transferred | Avg Transfer Rate | Started At | Finished At | Duration |

| bucket-1 | Failed | 0B | 0B/s | Mon, 29 Mar 2021 11:58:09 -0700 | Mon, 29 Mar 2021 11:59:10 -0700 | 1m1s |

|

| Mutations | Deletions | Expirations |

| --------- | --------- | ----------- |

| Received | Errored | Skipped | Received | Errored | Skipped | Received | Errored | Skipped |

| 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |

Example: performance run hits the second issue.

[http://perf.jenkins.couchbase.com/job/leto/17806/]
{quote}2021-03-29T02:22:17 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host http://leto-srv-01.perf.couchbase.com --username Administrator --password password --threads 16 --storage forestdb

Fatal error: local() encountered an error (return code 1) while executing './opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host http://leto-srv-01.perf.couchbase.com --username Administrator --password password --threads 16 --storage forestdb'

Aborting.
{quote}

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{quote}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{quote}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

*1. backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt

2. *Backup failed at the beginning*: During my investigation, my runs hit another issue. I check other backup performance runs and saw they failed because of the same issue. Please find output below. The log file of this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115941.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_57_52.872118914-07_00'

Transferring key value data for bucket 'bucket-1' at 0B/s (about 1h59m42s remaining) 0 items / 0B

[== ] 1.06%

Error backing up cluster: operation has timed out

!Screen Shot 2021-03-29 at 2.04.14 PM.png|width=800,height=250!

Example: performance run hits the second issue.

[http://perf.jenkins.couchbase.com/job/leto/17806/]
{quote}2021-03-29T02:22:17 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host [http://leto-srv-01.perf.couchbase.com|http://leto-srv-01.perf.couchbase.com/] --username Administrator --password password --threads 16 --storage forestdb

Fatal error: local() encountered an error (return code 1) while executing './opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host [http://leto-srv-01.perf.couchbase.com|http://leto-srv-01.perf.couchbase.com/] --username Administrator --password password --threads 16 --storage forestdb'

Aborting.
{quote}

Patrick Varley added a comment - 29/Mar/21 2:33 PM

Bo-Chun Wang As there are two different issues here, can you open a second defect please as we do not want to confuse things.

Focusing on the logs for 2021-03-29T115703, the last message before the program was terminated was:

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 915) Stream has been inactive for 1m0s, last seqno 46 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 647) Stream has been inactive for 1m0s, last seqno 68 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 835) Stream has been inactive for 1m0s, last seqno 44 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 739) Stream has been inactive for 1m0s, last seqno 84 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 1010) Stream has been inactive for 1m0s, last seqno 52 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 76) Stream has been inactive for 1m0s, last seqno 56 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252

2021-03-29T11:53:20.987-07:00 (Signal Handler) Signal `interrupt` received, exiting

goroutine 35 [running]:

This suggests that cbbackupmgr has not hanged and is wait on data for these vBuckets.

Following vb 76 we can see that the stream was opened as follows:

2021-03-29T11:49:00.388-07:00 (DCP) (bucket-1) (vb 76) Creating DCP stream | {"uuid":26490595435443,"start_seqno":0,"end_seqno":102,"snap_start":0,"snap_end":0,"retries":0}

At the time cbbackupmgr detected that no traffice has been send for vb 76 for one minute and the last seqno it had seen was 56.

There can be a number of cause for this, including network issues and server side problem. Can you please provide the server side logs so we can investigate this further.

Patrick Varley added a comment - 29/Mar/21 2:33 PM Bo-Chun Wang As there are two different issues here, can you open a second defect please as we do not want to confuse things. Focusing on the logs for 2021-03-29T115703, the last message before the program was terminated was: 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 915) Stream has been inactive for 1m0s, last seqno 46 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 647) Stream has been inactive for 1m0s, last seqno 68 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 835) Stream has been inactive for 1m0s, last seqno 44 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 739) Stream has been inactive for 1m0s, last seqno 84 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 1010) Stream has been inactive for 1m0s, last seqno 52 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:51:00.369-07:00 WARN: (DCP) (bucket-1) (vb 76) Stream has been inactive for 1m0s, last seqno 56 -- couchbase.(*DCPAsyncWorker).monitorActivity.func1() at dcp_async_worker.go:252 2021-03-29T11:53:20.987-07:00 (Signal Handler) Signal `interrupt` received, exiting goroutine 35 [running]: This suggests that cbbackupmgr has not hanged and is wait on data for these vBuckets. Following vb 76 we can see that the stream was opened as follows: 2021-03-29T11:49:00.388-07:00 (DCP) (bucket-1) (vb 76) Creating DCP stream | {"uuid":26490595435443,"start_seqno":0,"end_seqno":102,"snap_start":0,"snap_end":0,"retries":0} At the time cbbackupmgr detected that no traffice has been send for vb 76 for one minute and the last seqno it had seen was 56. There can be a number of cause for this, including network issues and server side problem. Can you please provide the server side logs so we can investigate this further.

Patrick Varley made changes - 29/Mar/21 2:33 PM

Assignee

Daniel Owen [ owend ]

Bo-Chun Wang [ bo-chun.wang ]

Patrick Varley added a comment - 29/Mar/21 2:43 PM - edited

Move the commend to ~~MB-45322~~ as it's related to that issue (to issues was raised in the one defect)

Patrick Varley added a comment - 29/Mar/21 2:43 PM - edited Move the commend to MB-45322 as it's related to that issue (to issues was raised in the one defect)

Patrick Varley made changes - 29/Mar/21 2:44 PM

Triage

Untriaged [ 10351 ]

Triaged [ 10350 ]

Patrick Varley added a comment - 29/Mar/21 2:45 PM - edited

Bo-Chun Wang Has any failures been reported on couchstore, I wonder if both are related to magma?

Patrick Varley added a comment - 29/Mar/21 2:45 PM - edited Bo-Chun Wang Has any failures been reported on couchstore, I wonder if both are related to magma?

Bo-Chun Wang added a comment - 29/Mar/21 2:45 PM

I'm opening another issue for the second defect.

Server logs:
https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.72.zip
https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.73.zip
https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.78.zip

Bo-Chun Wang added a comment - 29/Mar/21 2:45 PM I'm opening another issue for the second defect. Server logs: https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.72.zip https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.73.zip https://s3.amazonaws.com/bugdb/jira/qe/collectinfo-2021-03-29T214013-ns_1%40172.23.105.78.zip

Bo-Chun Wang added a comment - 29/Mar/21 2:51 PM - edited

Patrick Varley I have opened ~~MB-45322~~ for the second defect.

Bo-Chun Wang added a comment - 29/Mar/21 2:51 PM - edited Patrick Varley I have opened MB-45322 for the second defect.

Bo-Chun Wang made changes - 29/Mar/21 2:52 PM

Assignee

Bo-Chun Wang [ bo-chun.wang ]

Patrick Varley [ pvarley ]

Patrick Varley added a comment - 29/Mar/21 2:56 PM - edited

I'm going to clean up this defect and move the comments over to the correct defect, as it has already start to get confusing. This is why one issue one defect.

Patrick Varley added a comment - 29/Mar/21 2:56 PM - edited I'm going to clean up this defect and move the comments over to the correct defect, as it has already start to get confusing. This is why one issue one defect.

Patrick Varley made changes - 29/Mar/21 2:58 PM

Description

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{quote}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{quote}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

*1. backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt

2. *Backup failed at the beginning*: During my investigation, my runs hit another issue. I check other backup performance runs and saw they failed because of the same issue. Please find output below. The log file of this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115941.zip.

root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_57_52.872118914-07_00'

Transferring key value data for bucket 'bucket-1' at 0B/s (about 1h59m42s remaining) 0 items / 0B

[== ] 1.06%

Error backing up cluster: operation has timed out

!Screen Shot 2021-03-29 at 2.04.14 PM.png|width=800,height=250!

Example: performance run hits the second issue.

[http://perf.jenkins.couchbase.com/job/leto/17806/]
{quote}2021-03-29T02:22:17 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host [http://leto-srv-01.perf.couchbase.com|http://leto-srv-01.perf.couchbase.com/] --username Administrator --password password --threads 16 --storage forestdb

Fatal error: local() encountered an error (return code 1) while executing './opt/couchbase/bin/cbbackupmgr backup --archive /data/workspace/backup --repo default --host [http://leto-srv-01.perf.couchbase.com|http://leto-srv-01.perf.couchbase.com/] --username Administrator --password password --threads 16 --storage forestdb'

Aborting.
{quote}

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{noformat}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{noformat}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

*1. backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

{noformat}
root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt
{noformat}

Patrick Varley made changes - 29/Mar/21 2:58 PM

Description

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{noformat}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{noformat}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

*1. backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

{noformat}
root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt
{noformat}

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{noformat}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{noformat}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

* backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

{noformat}
root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt
{noformat}

Patrick Varley made changes - 29/Mar/21 2:58 PM

Attachment

cbbackupmgr-collectinfo-backup-2021-03-29T115941.zip [ 133130 ]

Patrick Varley made changes - 29/Mar/21 2:58 PM

Attachment

Screen Shot 2021-03-29 at 2.04.14 PM.png [ 133132 ]

Patrick Varley added a comment - 29/Mar/21 3:12 PM

Keeping on vBucket 76, from the server side logs we see the following:

021-03-29T11:49:00.391282-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Creating stream with start seqno 0 and end seqno 102; requested end seqno was 102, collections-m

anifest uid:0, filter:1 sid:none

2021-03-29T11:49:00.391340-07:00 INFO 2810: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_0 - (vb:109) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 0, end 101, and high completed

 none, max visible none

2021-03-29T11:49:00.391367-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Scheduling backfill from 1 to 102, reschedule flag : False

2021-03-29T11:49:01.155110-07:00 INFO (bucket-1) (bucket-1) magma_0 MagmaKVStore::initBySeqnoScanContext vb:76 seqno:1 endSeqno:102 purgeSeqno:0 nDocsToRead:102 docFilter:ALL_ITEMS valFilter:VALUES_COMPRESSED

2021-03-29T11:49:01.155202-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 0, end 102, and high completed none, max visible none

2021-03-29T11:49:05.077923-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Backfill complete, 0 items read from disk, 102 from memory, last seqno read: 102, pendingBackfill : False

2021-03-29T11:49:05.077947-07:00 INFO [(bucket-1) magma_0/kvstore-76/rev-000000001]0x7f7cbe16dd80 Ending seqno iterator (1=>102) with seqno 102

2021-03-29T11:49:05.078079-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Stream closing, sent until seqno 102 remaining items 0, reason: The stream ended due to all items being streamed

It looks like the server side sent the information as required and in a timely manor. This suggest the problem is the network or something internal to cbbackupmgr.

Patrick Varley added a comment - 29/Mar/21 3:12 PM Keeping on vBucket 76, from the server side logs we see the following: 021-03-29T11:49:00.391282-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Creating stream with start seqno 0 and end seqno 102; requested end seqno was 102, collections-m anifest uid:0, filter:1 sid:none 2021-03-29T11:49:00.391340-07:00 INFO 2810: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_0 - (vb:109) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 0, end 101, and high completed none, max visible none 2021-03-29T11:49:00.391367-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Scheduling backfill from 1 to 102, reschedule flag : False 2021-03-29T11:49:01.155110-07:00 INFO (bucket-1) (bucket-1) magma_0 MagmaKVStore::initBySeqnoScanContext vb:76 seqno:1 endSeqno:102 purgeSeqno:0 nDocsToRead:102 docFilter:ALL_ITEMS valFilter:VALUES_COMPRESSED 2021-03-29T11:49:01.155202-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 0, end 102, and high completed none, max visible none 2021-03-29T11:49:05.077923-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Backfill complete, 0 items read from disk, 102 from memory, last seqno read: 102, pendingBackfill : False 2021-03-29T11:49:05.077947-07:00 INFO [(bucket-1) magma_0/kvstore-76/rev-000000001]0x7f7cbe16dd80 Ending seqno iterator (1=>102) with seqno 102 2021-03-29T11:49:05.078079-07:00 INFO 2821: (bucket-1) DCP (Producer) eq_dcpq:cbbackupmgr_2021-03-29T11:48:57-07:00_57120_5 - (vb:76) Stream closing, sent until seqno 102 remaining items 0, reason: The stream ended due to all items being streamed It looks like the server side sent the information as required and in a timely manor. This suggest the problem is the network or something internal to cbbackupmgr.

Patrick Varley made changes - 29/Mar/21 3:22 PM

Description

Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it.

[http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{noformat}07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{noformat}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

* backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

{noformat}
root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt
{noformat}

+Probem+
Magma backup run failed on build 7.0.0-4797. The backup process was running for 14 hours until I killed it. [http://perf.jenkins.couchbase.com/job/rhea-5node2/952/]
{noformat}
07:01:02 2021-03-27T07:01:02 [INFO] Running: ./opt/couchbase/bin/cbbackupmgr backup --archive /workspace/backup --repo default --host [http://172.23.97.26|http://172.23.97.26/] --username Administrator --password password --threads 16 --storage sqlite

21:39:19 Build was aborted
{noformat}
I am able to reproduce this issue on VMs. During my investigation, my runs hit two different issues. I have collected logs and uploaded.

* backup was stuck:* Backup progress reached 99% and then stuck. I waited for several minutes and didn't see any progress. The run above should hit this issue. That's why it's running for 14 hours. The log file for this issue is cbbackupmgr-collectinfo-backup-2021-03-29t115703.zip.

{noformat}
root@ubuntu:/tmp/magma_backup# ./opt/couchbase/bin/cbbackupmgr backup --archive /tmp/backup --repo default --host [http://172.23.105.72|http://172.23.105.72/] --username Administrator --password password --threads 16 --storage sqlite

Backing up to '2021-03-29T11_48_51.331337778-07_00'

Transferring key value data for bucket 'bucket-1' at 123.39KiB/s (about 2s remaining) 99655 items / 31.87MiB

[=================================================================================================================================================================================================================================== ] 99.13%

^Cinterrupt
{noformat}

+Steps to reproduce+

+Expectation+
For backup to be successful

Patrick Varley added a comment - 29/Mar/21 3:24 PM

Bo-Chun Wang Thanks for the Server logs. It sounds like you're able to reproduce this easily, would it be possible to provide the steps please?

Patrick Varley added a comment - 29/Mar/21 3:24 PM Bo-Chun Wang Thanks for the Server logs. It sounds like you're able to reproduce this easily, would it be possible to provide the steps please?

Bo-Chun Wang added a comment - 29/Mar/21 3:30 PM

install cluster with build 7.0.0-4797
create a bucket and use magma as backend storage engineer
load 100,000 docs
start backup

Bo-Chun Wang added a comment - 29/Mar/21 3:30 PM install cluster with build 7.0.0-4797 create a bucket and use magma as backend storage engineer load 100,000 docs start backup

Patrick Varley made changes - 29/Mar/21 3:41 PM

Link

This issue relates to ~~MB-45322~~ [ ~~MB-45322~~ ]

Daniel Owen added a comment - 29/Mar/21 11:00 PM

In ~~MB-45322~~ Bo-Chun Wang noted that

I re-ran the same test on couchstore, and it finished successfully. The couchstore run didn't hit ~~MB-45320~~ and ~~MB-45322~~.

Therefore changing component to couchbase-bucket / storage-engine as its looks to be a magma issue.
Given that it affects only magma moving to CC.next

Daniel Owen added a comment - 29/Mar/21 11:00 PM In MB-45322 Bo-Chun Wang noted that I re-ran the same test on couchstore, and it finished successfully. The couchstore run didn't hit MB-45320 and MB-45322 . Therefore changing component to couchbase-bucket / storage-engine as its looks to be a magma issue. Given that it affects only magma moving to CC.next

Daniel Owen made changes - 29/Mar/21 11:00 PM

Fix Version/s		CheshireCat.Next [ 16908 ]
Fix Version/s	Cheshire-Cat [ 15915 ]

Daniel Owen made changes - 29/Mar/21 11:00 PM

Assignee

Patrick Varley [ pvarley ]

Daniel Owen [ owend ]

Daniel Owen made changes - 29/Mar/21 11:00 PM

Component/s		couchbase-bucket [ 10173 ]
Component/s		storage-engine [ 10175 ]
Component/s	tools [ 10223 ]

Daniel Owen made changes - 29/Mar/21 11:01 PM

Epic Link

~~MB-30659~~ [ 88207 ]

Daniel Owen made changes - 29/Mar/21 11:03 PM

Summary

Backup performance tests failed on 7.0.0-4797

[Magma] Backup performance tests failed on 7.0.0-4797

Patrick Varley added a comment - 30/Mar/21 12:47 AM

There is a possibility that is being caused by ~~GOCBC-1073~~. We are going to bump the gocbcore version, it would be worth knowing if you still hit this issue after that.

Patrick Varley added a comment - 30/Mar/21 12:47 AM There is a possibility that is being caused by GOCBC-1073 . We are going to bump the gocbcore version, it would be worth knowing if you still hit this issue after that.

Bo-Chun Wang added a comment - 30/Mar/21 9:50 AM

I have tried the test with build 4814 on VMs, and it works fine. I will do a full scale run to verify it.

Bo-Chun Wang added a comment - 30/Mar/21 9:50 AM I have tried the test with build 4814 on VMs, and it works fine. I will do a full scale run to verify it.

Bo-Chun Wang added a comment - 30/Mar/21 9:10 PM

I have a good run with build 4814.

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

Bo-Chun Wang added a comment - 30/Mar/21 9:10 PM I have a good run with build 4814. http://perf.jenkins.couchbase.com/job/rhea-5node1/896/

Daniel Owen made changes - 31/Mar/21 6:05 AM

Component/s		tools [ 10223 ]
Component/s	couchbase-bucket [ 10173 ]
Component/s	storage-engine [ 10175 ]

Daniel Owen made changes - 31/Mar/21 6:05 AM

Epic Link

~~MB-30659~~ [ 88207 ]

Daniel Owen made changes - 31/Mar/21 6:05 AM

Fix Version/s		Cheshire-Cat [ 15915 ]
Fix Version/s	CheshireCat.Next [ 16908 ]

Daniel Owen added a comment - 31/Mar/21 6:06 AM

Resolving as a duplicate of ~~GOCBC-1073~~

Daniel Owen added a comment - 31/Mar/21 6:06 AM Resolving as a duplicate of GOCBC-1073

Daniel Owen made changes - 31/Mar/21 6:06 AM

Link

This issue duplicates ~~GOCBC-1073~~ [ ~~GOCBC-1073~~ ]

Daniel Owen made changes - 31/Mar/21 6:20 AM

Resolution		Duplicate [ 3 ]
Status	Open [ 1 ]	Resolved [ 5 ]

Daniel Owen made changes - 31/Mar/21 6:20 AM

Assignee

Daniel Owen [ owend ]

Bo-Chun Wang [ bo-chun.wang ]

Mihir Kamdar (Inactive) added a comment - 01/Apr/21 4:20 PM

Bulk closing non-fixed defects. Feel free to reopen if necessary.

Mihir Kamdar (Inactive) added a comment - 01/Apr/21 4:20 PM Bulk closing non-fixed defects. Feel free to reopen if necessary.

Mihir Kamdar (Inactive) made changes - 01/Apr/21 4:20 PM

Status

Resolved [ 5 ]

Closed [ 6 ]

Lynn Straus made changes - 17/Jun/21 3:22 PM

Fix Version/s

7.0.0 [ 17233 ]

Lynn Straus made changes - 17/Jun/21 3:29 PM

Fix Version/s

Cheshire-Cat [ 15915 ]

Couchbase Server

[Magma] Backup performance tests failed on 7.0.0-4797

Details

Description

Attachments

Attachments

Issue Links

Gerrit Reviews

Activity

People

Dates

Gerrit Reviews

PagerDuty