RocksDB deleted some sst files around the time of the shutdown, but later re-opening db complained about missing those files
- Dominant language
- C++
- Stars
- 32.1k
- Forks
- 6.9k
- Avg merge
- 32m
- Merged PRs (30d)
- 1
Description
### Expected behavior
Normal shutdown of the DB, and re-opening of the DB should succeed.
### Actual behavior
Normal shutdown of the DB, but re-opening of the DB failed and complained about missing files due to deleted sst files.
### Steps to reproduce the behavior
I can't reproduce it easily. But it happened sometimes in our production system. Here is what I captured.
The last few lines of the LOG file showing deletion of sst files along with shutdown.
`2021/11/13-20:33:37.843454 7febe0ded700 [/db_impl/db_impl.cc:803] Storing 159 stats with timestamp 1636835617 to in-memory stats history
2021/11/13-20:33:37.843554 7febe0ded700 [/db_impl/db_impl.cc:816] [Pre-GC] In-memory stats history size: 1055060 bytes, slice count: 142
2021/11/13-20:33:37.843639 7febe0ded700 [/db_impl/db_impl.cc:825] [Post-GC] In-memory stats history size: 1055060 bytes, slice count: 141
2021/11/13-20:38:54.978475 7fec913d9700 [/db_impl/db_impl.cc:447] Shutdown: canceling all background work
2021/11/13-20:38:55.004287 7fec913d9700 [le/delete_scheduler.cc:73] Deleted file /path/to/rocksdb/048559.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2021/11/13-20:38:55.004317 7fec913d9700 EVENT_LOG_v1 {"time_micros": 1636835935004312, "job": 7943, "event": "table_file_deletion", "file_number": 48559}
2021/11/13-20:38:55.008765 7fec913d9700 [le/delete_scheduler.cc:73] Deleted file /path/to/rocksdb/048526.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2021/11/13-20:38:55.008778 7fec913d9700 EVENT_LOG_v1 {"time_micros": 1636835935008776, "job": 7943, "event": "table_file_deletion", "file_number": 48526}
2021/11/13-20:38:55.013012 7fec913d9700 [le/delete_scheduler.cc:73] Deleted file /path/to/rocksdb/048510.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2021/11/13-20:38:55.013022 7fec913d9700 EVENT_LOG_v1 {"time_micros": 1636835935013020, "job": 7943, "event": "table_file_deletion", "file_number": 48510}
2021/11/13-20:38:55.017648 7fec913d9700 [le/delete_scheduler.cc:73] Deleted file /path/to/rocksdb/048497.sst immediately, rate_bytes_per_sec 0, total_trash_size 0 max_trash_db_ratio 0.250000
2021/11/13-20:38:55.017658 7fec913d9700 EVENT_LOG_v1 {"time_micros": 1636835935017656, "job": 7943, "event": "table_file_deletion", "file_number": 48497}
2021/11/13-20:38:55.130709 7fec913d9700 [/db_impl/db_impl.cc:625] Shutdown complete`
When the DB was re-opened, it failed and complained about missing files because 048510.sst has been deleted. When the sst file is missing, RocksDB falls back to look for the ldb file, which doesn’t exist either.
`21:00:02.950 [pool-2-thread-2] ERROR c.e.c.d.d.c.impl.RocksDBConnection - initDBs org.rocksdb.RocksDBException: Corruption: IO error: No such file or directoryWhile open a file for random read: /path/to/rocksdb/048510.ldb: No such file or directory
at org.rocksdb.RocksDB.open(Native Method)
at org.rocksdb.RocksDB.open(RocksDB.java:306)`
We have a way to work around this issue because we took snapshot of the RocksDB instance. When this issue happens, we copy the deleted sst files back to the RocksDB folder and re-opening can succeed.
After the re-opening, the files we copied back to work around the issue would be deleted in a normal way in compaction later.
We are using version 6.15.5. My impression is the shutdown of the DB makes the deletion incomplete. It deleted the files but somewhere the metadata was not updated. The re-opening thought those files should still be available. Please advice and check the codes to see if any race condition during the shutdown can cause this issue. Thanks!!
Contributor guide
Assessment
This issue has not been assessed yet.