Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-55467

[CDC] History might be wrongly discarded at SetVBState (warmup included) and Compaction

    XMLWordPrintable

Details

    Description

      Steps to repro:

      1. Create a three node cluster
      2. Create three magma buckets with (history_retention_collection_default=true,bucket_history_retention_seconds=86400,bucket_history_retention_bytes=96636764160)
      3. Create four collections(total collections including default are five)
      4. Create 1 million items in each of the non default collection.(doc size : 1024 bytes)
      5. Start new doc:ops(update:delete)
      6. While doc ops are going on keep crashing memcached (sleep between two SIGKILL is 60 to 90 seconds)
      7. Once above doc ops are finsihed recreate delete docs

      Observed history getting toggled in memcached logs( Below logs are from 172.23.107.126)

      Logs:

      grep -r "history mode" * | grep "KVStore:(magma.0) magma_0/kvstore-0"
      		 
      memcached.log.000043.txt:2023-02-07T01:13:25.046923-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6127
      		 
      memcached.log.000043.txt:2023-02-07T01:13:52.954315-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6127
      		 
      memcached.log.000043.txt:2023-02-07T01:14:05.716382-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6127 updated to mode:0 set at seqno:0
      		 
      memcached.log.000043.txt:2023-02-07T01:14:08.757615-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6134
      		 
      memcached.log.000044.txt:2023-02-07T01:15:17.146735-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6134 updated to mode:0 set at seqno:0
      		 
      memcached.log.000044.txt:2023-02-07T01:15:45.478747-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6364
      		 
      memcached.log.000045.txt:2023-02-07T01:16:49.224251-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6364 updated to mode:0 set at seqno:0
      		 
      memcached.log.000045.txt:2023-02-07T01:16:55.673254-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6380
      		 
      memcached.log.000046.txt:2023-02-07T01:18:05.231672-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6380 updated to mode:0 set at seqno:0
      		 
      memcached.log.000047.txt:2023-02-07T01:18:34.370218-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6546
      		 
      memcached.log.000047.txt:2023-02-07T01:19:10.577836-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6546 updated to mode:0 set at seqno:0
      		 
      memcached.log.000048.txt:2023-02-07T01:19:52.763708-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6696
      		 
      memcached.log.000049.txt:2023-02-07T01:20:33.153879-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6696 updated to mode:0 set at seqno:0
      		 
      memcached.log.000049.txt:2023-02-07T01:21:03.661226-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6835
      		 
      memcached.log.000050.txt:2023-02-07T01:21:54.734583-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6835 updated to mode:0 set at seqno:0
      		 
      memcached.log.000050.txt:2023-02-07T01:22:00.107941-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6949
      		 
      memcached.log.000051.txt:2023-02-07T01:23:15.469646-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6949 updated to mode:0 set at seqno:0
      		 
      memcached.log.000051.txt:2023-02-07T01:23:25.443180-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:6974
      		 
      memcached.log.000052.txt:2023-02-07T01:24:48.309351-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:6974 updated to mode:0 set at seqno:0
      		 
      memcached.log.000053.txt:2023-02-07T01:25:10.466875-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7086
      		 
      memcached.log.000053.txt:2023-02-07T01:26:06.639660-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7086 updated to mode:0 set at seqno:0
      		 
      memcached.log.000054.txt:2023-02-07T01:26:53.887106-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7218
      		 
      memcached.log.000054.txt:2023-02-07T01:27:00.267569-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7218
      		 
      memcached.log.000054.txt:2023-02-07T01:27:11.328831-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7218 updated to mode:0 set at seqno:0
      		 
      memcached.log.000055.txt:2023-02-07T01:27:54.517062-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7241
      		 
      memcached.log.000055.txt:2023-02-07T01:27:57.291420-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7241
      		 
      memcached.log.000056.txt:2023-02-07T01:28:07.626372-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7241 updated to mode:0 set at seqno:0
      		 
      memcached.log.000058.txt:2023-02-07T01:30:00.211397-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7242
      		 
      memcached.log.000058.txt:2023-02-07T01:30:18.119796-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7242
      		 
      memcached.log.000058.txt:2023-02-07T01:30:29.797868-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7242 updated to mode:0 set at seqno:0
      		 
      memcached.log.000059.txt:2023-02-07T01:31:13.606560-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7269
      		 
      memcached.log.000059.txt:2023-02-07T01:31:44.265741-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7269 updated to mode:0 set at seqno:0
      		 
      memcached.log.000059.txt:2023-02-07T01:32:01.820845-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7271
      		 
      memcached.log.000061.txt:2023-02-07T01:33:27.279120-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:1 set at seqno:7271 updated to mode:0 set at seqno:0
      		 
      memcached.log.000062.txt:2023-02-07T01:34:50.598738-08:00 INFO [(magma.0) magma_0/kvstore-0/rev-000000001]KVStore:(magma.0) magma_0/kvstore-0/rev-000000001 current history mode:0 set at seqno:0 updated to mode:1 set at seqno:7325

      Also observed after compaction(triggered thru UI) history is getting cleared, though history param are set to very high values

      [root@localhost ~]# /opt/couchbase/bin/magma_dump /data/magma.1/magma.0 --kvstore 0 --tree seq --treedata | grep random_keys00000991998
      		 
          {"Seqno":6620,"Sn":10833,"key":{"Ascii":" random_keys00000991998","Hex":"0a72616e646f6d5f6b6579733030303030393931393938","cid":10,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":6620,"deleted":true,"expiry":1675761840,"valueSize":0},"op":"update","valueLen":55}
      		 
          {"Seqno":6889,"Sn":11523,"key":{"Ascii":" random_keys00000991998","Hex":"0b72616e646f6d5f6b6579733030303030393931393938","cid":11,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":6889,"deleted":true,"expiry":1675762266,"valueSize":0},"op":"update","valueLen":55}
      		 
          {"Seqno":7097,"Sn":11929,"key":{"Ascii":" random_keys00000991998","Hex":"0972616e646f6d5f6b6579733030303030393931393938","cid":9,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":7097,"deleted":true,"expiry":1675762363,"valueSize":0},"op":"update","valueLen":55}
      		 
          {"Seqno":7154,"Sn":12076,"key":{"Ascii":" random_keys00000991998","Hex":"0872616e646f6d5f6b6579733030303030393931393938","cid":8,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":7154,"deleted":true,"expiry":1675762435,"valueSize":0},"op":"update","valueLen":55}
      		 
          {"Seqno":8709,"Sn":15637,"key":{"Ascii":" random_keys00000991998","Hex":"0b72616e646f6d5f6b6579733030303030393931393938","cid":11,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8709,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8739,"Sn":15599,"key":{"Ascii":" random_keys00000991998","Hex":"0972616e646f6d5f6b6579733030303030393931393938","cid":9,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8739,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8746,"Sn":15629,"key":{"Ascii":" random_keys00000991998","Hex":"0a72616e646f6d5f6b6579733030303030393931393938","cid":10,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8746,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8791,"Sn":15689,"key":{"Ascii":" random_keys00000991998","Hex":"0872616e646f6d5f6b6579733030303030393931393938","cid":8,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8791,"deleted":false,"valueSize":873},"op":"update","valueLen":924}

      After Compaction

      [root@localhost ~]# /opt/couchbase/bin/magma_dump /data/magma.1/magma.0 --kvstore 0 --tree seq --treedata | grep random_keys00000991998
      		 
          {"Seqno":8709,"Sn":15637,"key":{"Ascii":" random_keys00000991998","Hex":"0b72616e646f6d5f6b6579733030303030393931393938","cid":11,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8709,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8739,"Sn":15599,"key":{"Ascii":" random_keys00000991998","Hex":"0972616e646f6d5f6b6579733030303030393931393938","cid":9,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8739,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8746,"Sn":15629,"key":{"Ascii":" random_keys00000991998","Hex":"0a72616e646f6d5f6b6579733030303030393931393938","cid":10,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8746,"deleted":false,"valueSize":873},"op":"update","valueLen":924}
      		 
          {"Seqno":8791,"Sn":15689,"key":{"Ascii":" random_keys00000991998","Hex":"0872616e646f6d5f6b6579733030303030393931393938","cid":8,"namespace":"default"},"logicalSize":0,"meta":{"bySeqno":8791,"deleted":false,"valueSize":873},"op":"update","valueLen":924}

      QE-TEST:

      git fetch https://review.couchbase.org/TAF refs/changes/72/186272/3 && git checkout -b change-186272 FETCH_HEAD
      		 
      guides/gradlew --refresh-dependencies testrunner -P jython=/opt/jython/bin/jython -P 'args=-i /tmp/temp_vol_3.ini -p bucket_storage=magma,bucket_ram_quota=256,init_loading=False,bucket_eviction_policy=fullEviction,rerun=False -t storage.magma.magma_crash_recovery.MagmaCrashTests.test_magma_failures_with_CDC,nodes_init=3,skip_cleanup=True,num_items=1000000,doc_size=1024,batch_size=1000,sdk_timeout=60,log_level=info,infra_log_level=info,key_size=22,num_collections=5,ops_rate=20000,key_type=SimpleKey,vbuckets=1024,replicas=2,doc_ops=update:delete,test_itr=50,bucket_history_retention_seconds=86400,bucket_history_retention_bytes=96636764160,standard_buckets=3,magma_buckets=3,num_scopes=1,induce_failures=True -m rest'

      Attachments

        No reviews matched the request. Check your Options in the drop-down menu of this sections header.

        Activity

          People

            ankush.sharma Ankush Sharma
            ankush.sharma Ankush Sharma
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              PagerDuty