Details
-
Bug
-
Resolution: Fixed
-
Major
-
7.0.0
-
None
-
Untriaged
-
1
-
Yes
-
KV-Engine Sprint 2021 July, KV-Engine Sprint 2021 August
Description
For non-OSO snapshots, like when using a pre-7.0 analytics, ingestion progress is measured against the seqno reported by KV for a vbucket. In the attached logs for many ingestions of the travel_sample._default._default collection, the snapshot marker end seqno is higher than by GET_SEQNOS (0x48), and also the mutations returned on that vbucket.
e.g. for vbid 11, GET_SEQNOS on cid=0 reports 73, 73 is also the highest mutation received, but the snapshot marker that is sent indicates the end seqno of 75. This leaves analytics falsely reporting that it is behind KV by two mutations on this vbucket.
2021-07-15T22:14:35.831834+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Creating stream with start seqno 0 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-filter-size:1 sid:none
|
2021-07-15T22:14:35.831863+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0" backfill:true, seqno:76
|
2021-07-15T22:14:35.831884+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Scheduling backfill from 1 to 75, reschedule flag : False
|
2021-07-15T22:14:36.135609+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 0, end 75, and high completed none, max visible none
|
2021-07-15T22:14:36.135634+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::registerCursor name "eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0", backfill:true, seqno:76
|
2021-07-15T22:14:38.913987+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Backfill complete, 0 items read from disk, 27 from memory, last seqno read: 73, pendingBackfill : False
|
2021-07-15T22:14:38.914611+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::transitionState: Transitioning from backfilling to in-memory
|
2021-07-15T22:19:57.223053+00:00 WARNING 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Stream closing, sent until seqno 73 remaining items 0, reason: The stream closed early because the conn was disconnected
|
2021-07-15T22:20:24.965683+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Creating stream with start seqno 73 and end seqno 18446744073709551615; requested end seqno was 18446744073709551615, collections-filter-size:1 sid:none
|
2021-07-15T22:20:24.966208+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::scheduleBackfill_UNLOCKED register cursor with name "eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0" backfill:true, seqno:76
|
2021-07-15T22:20:24.966239+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Scheduling backfill from 74 to 75, reschedule flag : False
|
2021-07-15T22:20:25.043776+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::markDiskSnapshot: Sending disk snapshot with start 73, end 75, and high completed none, max visible none
|
2021-07-15T22:20:25.043801+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::registerCursor name "eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0", backfill:true, seqno:76
|
2021-07-15T22:20:25.600838+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Backfill complete, 0 items read from disk, 0 from memory, last seqno read: 73, pendingBackfill : False
|
2021-07-15T22:20:25.601331+00:00 INFO 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) ActiveStream::transitionState: Transitioning from backfilling to in-memory
|
2021-07-15T22:22:30.334474+00:00 WARNING 86: (travel-sample) DCP (Producer) eq_dcpq:cbas:Default.remote:travel-sample:c65ee530da749259b395715432ac30b5:0 - (vb:11) Stream closing, sent until seqno 73 remaining items 0, reason: The stream closed early because the conn was disconnected
|