In this case the removal process has already finished hours before, so
nothing is streaming anymore (but looking at the list of the transaction
logs left behind, could be some of the transaction finished while
decommission was still running).
We don't have secondary indexes,and no repairs were running.
I will try to reproduce it, are there any debug flags you think would help
next time?
On Wed, Apr 5, 2023 at 1:03 AM Jeff Jirsa <jji...@gmail.com> wrote:
> You will DEFINITELY not remove sstables obsoleted by compaction if they
> are being streamed out to neighbors. It would also not surprise me that if
> you have something holding a background reference to one of the sstables in
> the oldest/older compaction transaction logs, that the whole process may
> block waiting on the tidier to clean that up.
>
> Things that may hold references:
> - Validation compactions (repair)
> - Index build/rebuild
> - Streaming (repair, bootstrap, move, decom)
>
> If you have repairs running, you can try pausing/cancelling them and/or
> stopping validation/index_build compactions.
>
>
>
> On Tue, Apr 4, 2023 at 2:29 PM Gil Ganz <gilg...@gmail.com> wrote:
>
>> If it was just one instance I would just bounce it but the thing is this
>> happens when we join/remove nodes, and we have a lot of servers with this
>> issue (while before the join/remove we are on ~50% disk usage).
>> We found ourselves fighting with compaction to make sure we don't run out
>> of space.
>> Will open a ticket, thanks.
>>
>>
>> On Wed, Apr 5, 2023 at 12:10 AM Jeff Jirsa <jji...@gmail.com> wrote:
>>
>>> If you restart the node, it'll process/purge those compaction logs on
>>> startup, but you want them to purge/process now.
>>>
>>> I genuinely dont know when the tidier runs, but it's likely the case
>>> that you're too busy compaction to purge (though I don't know what exactly
>>> "too busy" means).
>>>
>>> Since you're close to 95% disk full, bounce one instance at a time to
>>> recover the space, but we probably need a JIRA to understand exactly what's
>>> blocking the tidier from running.
>>>
>>>
>>>
>>> On Tue, Apr 4, 2023 at 1:55 PM Gil Ganz <gilg...@gmail.com> wrote:
>>>
>>>> More information - from another node in the cluster
>>>>
>>>> I can see many txn files although I only have two compactions running.
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# ls -l
>>>> *txn*
>>>> -rw-r--r-- 1 cassandra cassandra 613 Apr 4 05:26
>>>> nb_txn_compaction_09e3aa40-d2a7-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 461 Apr 4 10:17
>>>> nb_txn_compaction_11433360-d265-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 463 Apr 4 09:48
>>>> nb_txn_compaction_593e5320-d265-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 614 Apr 3 22:47
>>>> nb_txn_compaction_701d62d0-d264-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 136 Apr 3 22:27
>>>> nb_txn_compaction_bb770b50-d26e-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 463 Apr 4 09:23
>>>> nb_txn_compaction_ce51bfe0-d264-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 134 Apr 4 10:31
>>>> nb_txn_compaction_d17c7380-d2d3-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 464 Apr 4 09:24
>>>> nb_txn_compaction_ed7fc650-d264-11ed-b76b-3b279f6334bc.log
>>>> -rw-r--r-- 1 cassandra cassandra 613 Apr 3 22:54
>>>> nb_txn_compaction_f456f3b0-d271-11ed-b76b-3b279f6334bc.log
>>>>
>>>> Let's take for example the one from "Apr 4 09:24"
>>>> I can see the matching log message in system.log
>>>>
>>>> INFO [CompactionExecutor:142085] 2023-04-04 09:24:29,892
>>>> CompactionTask.java:241 - Compacted (ed7fc650-d264-11ed-b76b-3b279f6334bc)
>>>> 2 sstables to
>>>> [/var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big,]
>>>> to level=0. 362.987GiB to 336.323GiB (~92% of original) in 43,625,742ms.
>>>> Read Throughput = 8.520MiB/s, Write Throughput = 7.894MiB/s, Row Throughput
>>>> = ~-11,482/s. 3,755,353,838 total partitions merged to 3,479,484,261.
>>>> Partition merge counts were {1:3203614684, 2:275869577, }
>>>>
>>>>
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# cat
>>>> nb_txn_compaction_ed7fc650-d264-11ed-b76b-3b279f6334bc.log
>>>>
>>>> ADD:[/var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-,0,8][2633027732]
>>>>
>>>> REMOVE:[/var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-,1680543675071,8][4190572643]
>>>>
>>>> REMOVE:[/var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12109-big-,1680554352704,8][3101929253]
>>>> COMMIT:[,0,0][2613697770]
>>>>
>>>> I would expect sstable 10334 to be gone, since compaction finished an
>>>> hour ago, but files are still there.
>>>>
>>>>
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# ls -l
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-*
>>>> -rw-r--r-- 1 cassandra cassandra 315582480 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-CompressionInfo.db
>>>> -rw-r--r-- 1 cassandra cassandra 361124597166 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Data.db
>>>> -rw-r--r-- 1 cassandra cassandra 10 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Digest.crc32
>>>> -rw-r--r-- 1 cassandra cassandra 4316334488 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Filter.db
>>>> -rw-r--r-- 1 cassandra cassandra 283651305837 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Index.db
>>>> -rw-r--r-- 1 cassandra cassandra 11934 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Statistics.db
>>>> -rw-r--r-- 1 cassandra cassandra 763353245 Apr 3 17:41
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Summary.db
>>>> -rw-r--r-- 1 cassandra cassandra 92 Mar 24 16:46
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-TOC.txt
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# ls -l
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-*
>>>> -rw-r--r-- 1 cassandra cassandra 315582480 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-CompressionInfo.db
>>>> -rw-r--r-- 1 cassandra cassandra 361124597166 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Data.db
>>>> -rw-r--r-- 1 cassandra cassandra 10 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Digest.crc32
>>>> -rw-r--r-- 1 cassandra cassandra 4316334488 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Filter.db
>>>> -rw-r--r-- 1 cassandra cassandra 283651305837 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Index.db
>>>> -rw-r--r-- 1 cassandra cassandra 11934 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Statistics.db
>>>> -rw-r--r-- 1 cassandra cassandra 709470839 Apr 4 09:41
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-Summary.db
>>>> -rw-r--r-- 1 cassandra cassandra 92 Apr 4 09:24
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-12142-big-TOC.txt
>>>>
>>>>
>>>> Disk space and du command shows the following :
>>>>
>>>> [user@server808 disk1]# df -h
>>>> /dev/mapper/data_vg-cass_lv 7.0T 6.6T 411G 95%
>>>> /var/lib/cassandra/data/disk1
>>>> [user@server808 disk1]# du . -h|grep T
>>>> 6.6T ./kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a
>>>> 6.6T ./kt_ks
>>>> 6.6T .
>>>>
>>>>
>>>> If i run sstableutil to clean things up, df command still shows space
>>>> as occupied, but now du shows reduction, and files appear in lsof output
>>>>
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]#
>>>> sstableutil -c -v kt_ks new_table
>>>> Warning: Maximum heap size rounded up to 512 MB
>>>> WARN 10:52:18,106 memtable_cleanup_threshold has been deprecated and
>>>> should be removed from cassandra.yaml
>>>> Cleaning up...
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# df -h
>>>> /dev/mapper/data_vg-cass_lv 7.0T 6.6T 432G 94%
>>>> /var/lib/cassandra/data/disk1
>>>> [user@server808 new_table-44263b406bf111ed8bd9df80ace3677a]# ls -l
>>>> *txn*
>>>> ls: cannot access *txn*: No such file or directory
>>>> [user@server808 disk1]# du . -h|grep T
>>>> 3.8T ./kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a
>>>> 3.8T ./kt_ks
>>>> 3.8T .
>>>>
>>>>
>>>> lsof|grep deleted output contains many rows like this :
>>>>
>>>> LocalPool 38608 40310 cassandra 879r REG 253,3
>>>> 283651305837 4297002780
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Index.db
>>>> (deleted)
>>>> LocalPool 38608 40310 cassandra 1061r REG 253,3
>>>> 361124597166 4297002778
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Data.db
>>>> (deleted)
>>>> OptionalT 38608 40352 cassandra 879r REG 253,3
>>>> 283651305837 4297002780
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Index.db
>>>> (deleted)
>>>> OptionalT 38608 40352 cassandra 1061r REG 253,3
>>>> 361124597166 4297002778
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Data.db
>>>> (deleted
>>>> logback-4 38608 40439 cassandra 1061r REG 253,3
>>>> 361124597166 4297002778
>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-10334-big-Data.db
>>>> (deleted)
>>>>
>>>>
>>>> I will add that this cluster contains a single table with twcs.
>>>>
>>>> gil
>>>>
>>>>
>>>> On Tue, Apr 4, 2023 at 10:14 AM Gil Ganz <gilg...@gmail.com> wrote:
>>>>
>>>>> Hey
>>>>> I have a 4.0.7 cluster in which I see weird behavior.
>>>>> I expect that once compaction finishes, the old sstables that were
>>>>> part of the compaction set will be deleted, but it appears they are
>>>>> deleted
>>>>> much later, thus causing space issues.
>>>>>
>>>>> For example this is what I have in the log, only one compaction
>>>>> finished, which took as input 3 sstables, but I can see many sstables were
>>>>> deleted afterwards:
>>>>>
>>>>>
>>>>> INFO [CompactionExecutor:17344] 2023-04-04 04:39:07,345
>>>>> CompactionTask.java:241 - Compacted (489ddc80-d282-11ed-b4fb-d9d812cda140)
>>>>> 3 sstables to
>>>>> [/var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5685-big,]
>>>>> to level=0. 140.672GiB to 134.554GiB (~95% of original) in 13,894,920ms.
>>>>> Read Throughput = 10.367MiB/s, Write Throughput = 9.916MiB/s, Row
>>>>> Throughput = ~-80,450/s. 1,425,146,188 total partitions merged to
>>>>> 1,378,482,110. Partition merge counts were {1:1339149089, 2:32001964,
>>>>> 3:7331057, }
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:08,151 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5546-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:09,399 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5424-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:10,563 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5677-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:12,143 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-3360-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:12,754 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5604-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:13,328 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5572-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:13,340 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5684-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:13,363 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-5630-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:14,492 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-4991-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:16,338 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-2537-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:18,287 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-4171-big
>>>>> INFO [NonPeriodicTasks:1] 2023-04-04 04:39:21,467 SSTable.java:111 -
>>>>> Deleting sstable:
>>>>> /var/lib/cassandra/data/disk1/kt_ks/new_table-44263b406bf111ed8bd9df80ace3677a/nb-1767-big
>>>>>
>>>>>
>>>>> Am I missing something about how/when sstables are deleted? Is there
>>>>> something I can do to control when that delete happens?
>>>>>
>>>>> gil
>>>>>
>>>>
