facebook / facebook/rocksdb

Compaction cause data loss when using snapshot.

Open
#10,377 1 comment 0 reactions 0 assignees View on GitHub
question up-for-grabs
Dominant language
C++
Stars
32.1k
Forks
6.9k
Avg merge
32m
Merged PRs (30d)
1

Description

> Note: Please use Issues only for bug reports. For questions, discussions, feature requests, etc. post to dev group: https://groups.google.com/forum/#!forum/rocksdb or https://www.facebook.com/groups/rocksdb.dev

Use `6.27.3` in `Java` through `JNI`

Currently, we use `Async + DisableWAL` to write data and `snapshot + RaftLog` to recover data in the event of a node crash.

```
this.writeOptions = new WriteOptions();
this.writeOptions.setSync(false);
this.writeOptions.setDisableWAL(true);
```

We found some data loss problems that seem to occur in the compaction.

### Expected behavior
Don't lose data.

### Actual behavior
Lose some `MemTable` data after compaction.

### Steps to reproduce the behavior
1. Using `ingestExternalFile` to load data (Default CF has 1000003 keys)
2. Start writing data and keep writing (Update some value)
3. Call `getSnapshot` to hold a snapshot and use `SstFileWriter` write some SST as a backup
4. Lost data (The default CF has only 500000 keys left but we didn't delete any data.)

I looked at the rocksdb's log and the `MemTable` data seemed to be lost after compaction. But for me, it's hard to reproduce the problem. This does not happen very often.

Log at the time:
```
2022/07/15-12:37:31.933533 139706018649856 [/db_impl/db_impl_write.cc:1817] [default] New memtable created with log file: #5. Immutable memtables: 0.
2022/07/15-12:37:31.933602 139706431497984 (Original Log Time 2022/07/15-12:37:31.933584) [/db_impl/db_impl_compaction_flush.cc:2701] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
2022/07/15-12:37:31.933607 139706431497984 [/flush_job.cc:819] [default] [JOB 47] Flushing memtable with next log file: 5
2022/07/15-12:37:31.933624 139706431497984 EVENT_LOG_v1 {"time_micros": 1657859851933620, "job": 47, "event": "flush_started", "num_memtables": 1, "num_entries": 688607, "num_deletes": 0, "total_data_size": 54376987, "memory_usage": 66849928, "flush_reason": "Write Buffer Full"}
2022/07/15-12:37:31.933626 139706431497984 [/flush_job.cc:848] [default] [JOB 47] Level-0 flush table #74: started
2022/07/15-12:37:32.219364 139706431497984 EVENT_LOG_v1 {"time_micros": 1657859852219321, "cf_name": "default", "job": 47, "event": "table_file_creation", "file_number": 74, "file_size": 11761092, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 10918417, "index_size": 199743, "index_partitions": 100, "top_level_index_size": 3599, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 751862, "raw_key_size": 13445496, "raw_average_key_size": 36, "raw_value_size": 15300527, "raw_average_value_size": 40, "num_data_blocks": 5488, "num_entries": 373486, "num_filter_entries": 373486, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "rocksdb.BuiltinBloomFilter", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "StringAppendOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "LZ4", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; ", "creation_time": 1657859726, "oldest_key_time": 1657859726, "file_creation_time": 1657859851, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "e81605f7-b4dc-4bb0-a0e2-424318082866", "db_session_id": "WIJBUZGZ8Z3ZE68SMEVP", "orig_file_number": 74}}
2022/07/15-12:37:32.219383 139706431497984 [/flush_job.cc:937] [default] [JOB 47] Level-0 flush table #74: 11761092 bytes OK
2022/07/15-12:37:32.219392 139706431497984 [/flush_job.cc:986] [default] [JOB 47] Flush lasted 285796 microseconds, and 281242 cpu microseconds.
2022/07/15-12:37:32.219423 139706431497984 [/version_set.cc:3746] More existing levels in DB than needed. max_bytes_for_level_multiplier may not be guaranteed.
2022/07/15-12:37:32.220199 139706431497984 (Original Log Time 2022/07/15-12:37:32.219396) [/memtable_list.cc:471] [default] Level-0 commit table #74 started
2022/07/15-12:37:32.220203 139706431497984 (Original Log Time 2022/07/15-12:37:32.220105) [/memtable_list.cc:675] [default] Level-0 commit table #74: memtable #1 done
2022/07/15-12:37:32.220206 139706431497984 (Original Log Time 2022/07/15-12:37:32.220130) EVENT_LOG_v1 {"time_micros": 1657859852220122, "job": 47, "event": "flush_finished", "output_compression": "LZ4", "lsm_state": [4, 0, 0, 0, 0, 0, 1], "immutable_memtables": 0}
2022/07/15-12:37:32.220208 139706431497984 (Original Log Time 2022/07/15-12:37:32.220170) [/db_impl/db_impl_compaction_flush.cc:264] [default] Level summary: base level 6 level multiplier 10.00 max bytes base 268435456 files[4 0 0 0 0 0 1] max score 1.00
2022/07/15-12:37:32.220257 139706441987840 [/compaction/compaction_job.cc:2334] [default] [JOB 48] Compacting 4@0 + 1@6 files to L6, score 1.00
2022/07/15-12:37:32.220272 139706441987840 [/compaction/compaction_job.cc:2338] [default] Compaction start summary: Base version 54 Base level 0, inputs: [74(11MB) 63(11MB) 57(11MB) 51(11MB)], [12(21MB)]
2022/07/15-12:37:32.220287 139706441987840 EVENT_LOG_v1 {"time_micros": 1657859852220279, "job": 48, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [74, 63, 57, 51], "files_L6": [12], "score": 1, "input_data_size": 69355313}
2022/07/15-12:37:33.432295 139706441987840 [/compaction/compaction_job.cc:1942] [default] [JOB 48] Generated table #75: 995878 keys, 27136482 bytes
2022/07/15-12:37:33.432348 139706441987840 EVENT_LOG_v1 {"time_micros": 1657859853432321, "cf_name": "default", "job": 48, "event": "table_file_creation", "file_number": 75, "file_size": 27136482, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 25781315, "index_size": 675060, "index_partitions": 267, "top_level_index_size": 12799, "index_key_is_user_key": 0, "index_value_is_delta_encoded": 1, "filter_size": 1018607, "raw_key_size": 35851608, "raw_average_key_size": 36, "raw_value_size": 40798120, "raw_average_value_size": 40, "num_data_blocks": 13824, "num_entries": 995878, "num_filter_entries": 498199, "num_deletions": 0, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "rocksdb.BuiltinBloomFilter", "column_family_name": "default", "column_family_id": 0, "comparator": "leveldb.BytewiseComparator", "merge_operator": "StringAppendOperator", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "LZ4", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; max_dict_buffer_bytes=0; ", "creation_time": 1657854227, "oldest_key_time": 0, "file_creation_time": 1657859852, "slow_compression_estimated_data_size": 0, "fast_compression_estimated_data_size": 0, "db_id": "e81605f7-b4dc-4bb0-a0e2-424318082866", "db_session_id": "WIJBUZGZ8Z3ZE68SMEVP", "orig_file_number": 75}}
2022/07/15-12:37:33.435344 139706441987840 [/compaction/compaction_job.cc:2002] [default] [JOB 48] Compacted 4@0 + 1@6 files to L6 => 27136482 bytes
2022/07/15-12:37:33.436083 139706441987840 (Original Log Time 2022/07/15-12:37:33.436011) [/compaction/compaction_job.cc:962] [default] compacted to: base level 6 level multiplier 10.00 max bytes base 268435456 files[0 0 0 0 0 0 1] max score 0.00, MB/sec: 57.2 rd, 22.4 wr, level 6, files in(4, 1) out(1 +0 blob) MB in(44.8, 21.3 +0.0 blob) out(25.9 +0.0 blob), read-write-amplify(2.1) write-amplify(0.6) OK, records in: 2494331, records dropped: 1498453 output_compression: LZ4
2022/07/15-12:37:33.436088 139706441987840 (Original Log Time 2022/07/15-12:37:33.436035) EVENT_LOG_v1 {"time_micros": 1657859853436023, "job": 48, "event": "compaction_finished", "compaction_time_micros": 1212087, "compaction_time_cpu_micros": 1198650, "output_level": 6, "num_output_files": 1, "total_output_size": 27136482, "num_input_records": 2494331, "num_output_records": 995878, "num_subcompactions": 1, "output_compression": "LZ4", "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [0, 0, 0, 0, 0, 0, 1]}
2022/07/15-12:41:17.197684 139706274150144 [/db_impl/db_impl.cc:1005] ------- DUMPING STATS -------
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.