I have 2 kafka streams state stores implemented. They are both persistent key value stores. The problem that I am facing is the compaction of rocksdb is happening only in one of the state stores and the other state store is just piling on more sst files and in turn increasing the disk space. I tried to debug the rocksdb logs. Everything looked fine there. The compactions were happening fine for one of the state stores and there was no info related to another store. Can anyone please help on this aspect?
To add more helpful info, this is happening only inside the container. I tried to replicate this with a sample app in my local developer environment, there were no issues there.
Edit:
I was able to print the rocksdb logs at the KV store level and found some interesting aspects. The compaction was happening but the files were not getting deleted. Here are the logs. I found the levels kept increasing. Can anyone explain why the levels are increasing?
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.182015) [db/db_impl_compaction_flush.cc:140] [default] Level summary: **files[9 0 0 0 0 0 1]** max score 1.00
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183102) [db/compaction_picker_universal.cc:473] [default] Universal: Possible candidate file 58[0].
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183113) [db/compaction_picker_universal.cc:525] [default] Universal: Skipping file 58[0] with size 4244 (compensated size 4244)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183116) [db/compaction_picker_universal.cc:473] [default] Universal: Possible candidate file 57[1].
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183298) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 57[1] with size 6522 (compensated size 6522)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183301) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 56[2] with size 4245 (compensated size 4245)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183302) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 55[3] with size 6506 (compensated size 6506)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183303) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 54[4] with size 4244 (compensated size 4244)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183305) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 53[5] with size 6505 (compensated size 6505)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183306) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 52[6] with size 4244 (compensated size 4244)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183307) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 51[7] with size 6503 (compensated size 6503)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183309) [db/compaction_picker_universal.cc:594] [default] Universal: Picking file 50[8] with size 4245 (compensated size 4245)
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.183429) [db/compaction_picker_universal.cc:289] [default] Universal: compacting for size ratio
example_store: INFO_LEVEL: [db/compaction_job.cc:1437] [default] [JOB 51] Compacting 8@0 files to L5, score 1.00
example_store: INFO_LEVEL: [db/compaction_job.cc:1441] [default] Compaction start summary: Base version 46 Base level 0, inputs: [57(6522B) 56(4245B) 55(6506B) 54(4244B) 53(6505B) 52(4244B) 51(6503B) 50(4245B)], [], [], [], [], [], []
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770177193012, "job": 51, "event": "compaction_started", "files_L0": [57, 56, 55, 54, 53, 52, 51, 50], "files_L1": [], "files_L2": [], "files_L3": [], "files_L4": [], "files_L5": [], "files_L6": [], "score": 1, "input_data_size": 43014}
example_store: INFO_LEVEL: [db/compaction_job.cc:1132] [default] [JOB 51] Generated table #59: 32 keys, 9878 bytes
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770177315362, "cf_name": "default", "job": 51, "event": "table_file_creation", "file_number": 59, "file_size": 9878, "table_properties": {"data_size": 8826, "index_size": 296, "filter_size": 0, "raw_key_size": 910, "raw_average_key_size": 28, "raw_value_size": 29633, "raw_average_value_size": 926, "num_data_blocks": 8, "num_entries": 32, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/compaction_job.cc:1199] [default] [JOB 51] Compacted 8@0 files to L5 => 9878 bytes
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.357595) [db/compaction_job.cc:621] [default] compacted to: files[1 0 0 0 0 1 1] max score 0.30, MB/sec: 0.3 rd, 0.1 wr, level 5, files in(8, 0) out(1) MB in(0.0, 0.0) out(0.0), read-write-amplify(1.2) write-amplify(0.2) OK, records in: 128, records dropped: 96
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.357647) EVENT_LOG_v1 {"time_micros": 1560770177357627, "job": 51, "event": "compaction_finished", "compaction_time_micros": 142703, "output_level": 5, "num_output_files": 1, "total_output_size": 9878, "num_input_records": 128, "num_output_records": 32, "num_subcompactions": 1, "num_single_delete_mismatches": 0, "num_single_delete_fallthrough": 0, "lsm_state": [1, 0, 0, 0, 0, 1, 1]}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.358280) [db/compaction_picker_universal.cc:261] [default] Universal: nothing to do
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:16:17.358281) [db/db_impl_compaction_flush.cc:1518] Compaction nothing to do
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:17:47.147896) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 53] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770267148077, "job": 53, "event": "flush_started", "num_memtables": 1, "num_entries": 16, "num_deletes": 0, "memory_usage": 19704}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 53] Level-0 flush table #60: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770267150374, "cf_name": "default", "job": 53, "event": "table_file_creation", "file_number": 60, "file_size": 6502, "table_properties": {"data_size": 5514, "index_size": 186, "filter_size": 0, "raw_key_size": 455, "raw_average_key_size": 28, "raw_value_size": 17717, "raw_average_value_size": 1107, "num_data_blocks": 5, "num_entries": 16, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 53] Level-0 flush table #60: 6502 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:17:47.152018) [db/memtable_list.cc:372] [default] Level-0 commit table #60 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:17:47.153419) [db/memtable_list.cc:395] [default] Level-0 commit table #60: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:17:47.153437) EVENT_LOG_v1 {"time_micros": 1560770267153430, "job": 53, "event": "flush_finished", "lsm_state": [2, 0, 0, 0, 0, 1, 1], "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:17:47.153456) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[2 0 0 0 0 1 1] max score 0.40
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:18:17.170673) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 54] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770297170853, "job": 54, "event": "flush_started", "num_memtables": 1, "num_entries": 16, "num_deletes": 0, "memory_usage": 14224}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 54] Level-0 flush table #61: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770297174979, "cf_name": "default", "job": 54, "event": "table_file_creation", "file_number": 61, "file_size": 4244, "table_properties": {"data_size": 3293, "index_size": 107, "filter_size": 0, "raw_key_size": 455, "raw_average_key_size": 28, "raw_value_size": 11916, "raw_average_value_size": 744, "num_data_blocks": 3, "num_entries": 16, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 54] Level-0 flush table #61: 4244 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:18:17.177091) [db/memtable_list.cc:372] [default] Level-0 commit table #61 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:18:17.178570) [db/memtable_list.cc:395] [default] Level-0 commit table #61: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:18:17.178590) EVENT_LOG_v1 {"time_micros": 1560770297178582, "job": 54, "event": "flush_finished", "lsm_state": [3, 0, 0, 0, 0, 1, 1], "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:18:17.178614) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[3 0 0 0 0 1 1] max score 0.50
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:20:17.360151) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 55] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770417360328, "job": 55, "event": "flush_started", "num_memtables": 1, "num_entries": 32, "num_deletes": 0, "memory_usage": 32304}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 55] Level-0 flush table #62: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770417365009, "cf_name": "default", "job": 55, "event": "table_file_creation", "file_number": 62, "file_size": 9865, "table_properties": {"data_size": 8813, "index_size": 296, "filter_size": 0, "raw_key_size": 910, "raw_average_key_size": 28, "raw_value_size": 29633, "raw_average_value_size": 926, "num_data_blocks": 8, "num_entries": 32, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 55] Level-0 flush table #62: 9865 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:20:17.371008) [db/memtable_list.cc:372] [default] Level-0 commit table #62 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:20:17.373221) [db/memtable_list.cc:395] [default] Level-0 commit table #62: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:20:17.373274) EVENT_LOG_v1 {"time_micros": 1560770417373259, "job": 55, "event": "flush_finished", "lsm_state": [4, 0, 0, 0, 0, 1, 1], "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:20:17.373318) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[4 0 0 0 0 1 1] max score 0.60
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:22:17.625738) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 56] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770537625921, "job": 56, "event": "flush_started", "num_memtables": 1, "num_entries": 32, "num_deletes": 0, "memory_usage": 32360}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 56] Level-0 flush table #63: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770537647724, "cf_name": "default", "job": 56, "event": "table_file_creation", "file_number": 63, "file_size": 9858, "table_properties": {"data_size": 8807, "index_size": 296, "filter_size": 0, "raw_key_size": 910, "raw_average_key_size": 28, "raw_value_size": 29633, "raw_average_value_size": 926, "num_data_blocks": 8, "num_entries": 32, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 56] Level-0 flush table #63: 9858 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:22:17.666254) [db/memtable_list.cc:372] [default] Level-0 commit table #63 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:22:17.685689) [db/memtable_list.cc:395] [default] Level-0 commit table #63: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:22:17.685728) EVENT_LOG_v1 {"time_micros": 1560770537685714, "job": 56, "event": "flush_finished", "lsm_state": [5, 0, 0, 0, 0, 1, 1], "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:22:17.685761) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[5 0 0 0 0 1 1] max score 0.70
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:24:18.003063) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 57] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770658007107, "job": 57, "event": "flush_started", "num_memtables": 1, "num_entries": 32, "num_deletes": 0, "memory_usage": 32352}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 57] Level-0 flush table #64: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770658069543, "cf_name": "default", "job": 57, "event": "table_file_creation", "file_number": 64, "file_size": 9863, "table_properties": {"data_size": 8811, "index_size": 296, "filter_size": 0, "raw_key_size": 910, "raw_average_key_size": 28, "raw_value_size": 29633, "raw_average_value_size": 926, "num_data_blocks": 8, "num_entries": 32, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 57] Level-0 flush table #64: 9863 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:24:18.099968) [db/memtable_list.cc:372] [default] Level-0 commit table #64 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:24:18.136935) [db/memtable_list.cc:395] [default] Level-0 commit table #64: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:24:18.136965) EVENT_LOG_v1 {"time_micros": 1560770658136956, "job": 57, "event": "flush_finished", "lsm_state": [6, 0, 0, 0, 0, 1, 1], "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:24:18.136988) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[6 0 0 0 0 1 1] max score 0.80
example_store: INFO_LEVEL: [db/db_impl_write.cc:1127] [default] New memtable created with log file: #12. Immutable memtables: 0.
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:26:18.014309) [db/db_impl_compaction_flush.cc:1216] Calling FlushMemTableToOutputFile with column family [default], flush slots available 1, compaction slots available 1, flush slots scheduled 1, compaction slots scheduled 0
example_store: INFO_LEVEL: [db/flush_job.cc:264] [default] [JOB 58] Flushing memtable with next log file: 12
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770778014601, "job": 58, "event": "flush_started", "num_memtables": 1, "num_entries": 32, "num_deletes": 0, "memory_usage": 32312}
example_store: INFO_LEVEL: [db/flush_job.cc:293] [default] [JOB 58] Level-0 flush table #65: started
example_store: INFO_LEVEL: EVENT_LOG_v1 {"time_micros": 1560770778036112, "cf_name": "default", "job": 58, "event": "table_file_creation", "file_number": 65, "file_size": 9858, "table_properties": {"data_size": 8807, "index_size": 296, "filter_size": 0, "raw_key_size": 910, "raw_average_key_size": 28, "raw_value_size": 29633, "raw_average_value_size": 926, "num_data_blocks": 8, "num_entries": 32, "filter_policy_name": "", "kDeletedKeys": "0", "kMergeOperands": "0"}}
example_store: INFO_LEVEL: [db/flush_job.cc:324] [default] [JOB 58] Level-0 flush table #65: 9858 bytes OK
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:26:18.063192) [db/memtable_list.cc:372] [default] Level-0 commit table #65 started
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:26:18.082165) [db/memtable_list.cc:395] [default] Level-0 commit table #65: memtable #1 done
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:26:18.082203) EVENT_LOG_v1 {"time_micros": 1560770778082193, "job": 58, "event": "flush_finished", "lsm_state": **[7, 0, 0, 0, 0, 1, 1]**, "immutable_memtables": 0}
example_store: INFO_LEVEL: (Original Log Time 2019/06/17-11:26:18.082231) [db/db_impl_compaction_flush.cc:140] [default] Level summary: files[7 0 0 0 0 1 1] max score 0.90
The iterator has to be closed explicitly after using it. This was the main cause of the issue.