[
https://issues.apache.org/jira/browse/CASSANDRA-18125?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17649441#comment-17649441
]
Nicolas Henneaux edited comment on CASSANDRA-18125 at 12/19/22 7:06 PM:
------------------------------------------------------------------------
Thanks for your feedback, of course I can provide more details.
1. There is no secondary index in use.
2. Not sure what is really heavy but I don't believe it is heavy, each node has
~200GB of data with ttl of 10 days for most of the data (~20GB written by day).
About overwrite, I guess you mean updating some cells, yes we usually insert
then update a row within a short time frame (~10min).
3. I don't think off-heap is used. If disabled by default, that's not something
I enabled
A compaction was running it seems. I got a lot of
- TWCS skipping check for fully expired SSTables
- TWCS expired check sufficiently far in the past, checking for fully expired
SSTables
Here is an extract of the logs around ~1min
{code}
Dec 19, 2022 @ 13:07:51.334COMMIT-LOG-ALLOCATOR
org.apache.cassandra.db.ColumnFamilyStore logFlush - Enqueuing flush of T4:
35.156KiB (0%) on-heap, 0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:07:51.334COMMIT-LOG-ALLOCATOR
org.apache.cassandra.db.ColumnFamilyStore logFlush - Enqueuing flush of T3:
852.600KiB (0%) on-heap, 0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:07:51.334COMMIT-LOG-ALLOCATOR
org.apache.cassandra.db.ColumnFamilyStore logFlush - Enqueuing flush of T2:
41.210KiB (0%) on-heap, 0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:07:51.334COMMIT-LOG-ALLOCATOR
org.apache.cassandra.db.ColumnFamilyStore logFlush - Enqueuing flush of T1:
364.268KiB (0%) on-heap, 0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:07:15.561NonPeriodicTasks:1
org.apache.cassandra.io.sstable.SSTable delete - Deleting sstable:
/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-26-big
Dec 19, 2022 @ 13:07:15.560CompactionExecutor:6104
org.apache.cassandra.db.compaction.CompactionTask runMayThrow - Compacted
(ad77aef0-7f95-11ed-bab7-e7d7c3e60f28) 2 sstables to
[/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-29-big,]
to level=0. 5.429KiB to 5.426KiB (~99% of original) in 9ms. Read Throughput
= 593.925KiB/s, Write Throughput = 593.604KiB/s, Row Throughput = ~118/s. 59
total partitions merged to 58. Partition merge counts were {1:57, 2:1, }
Dec 19, 2022 @ 13:07:15.560NonPeriodicTasks:1
org.apache.cassandra.io.sstable.SSTable delete - Deleting sstable:
/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-27-big
Dec 19, 2022 @ 13:07:15.551MemtableReclaimMemory:2628
org.apache.cassandra.service.CassandraDaemon uncaughtException - Exception in
thread Thread[MemtableReclaimMemory:2628,5,main]java.lang.AssertionError: null
at
org.apache.cassandra.utils.memory.MemtablePool$SubPool.released(MemtablePool.java:193)
at
org.apache.cassandra.utils.memory.MemtableAllocator$SubAllocator.releaseAll(MemtableAllocator.java:151)
at
org.apache.cassandra.utils.memory.MemtableAllocator$SubAllocator.setDiscarded(MemtableAllocator.java:142)
at
org.apache.cassandra.utils.memory.MemtableAllocator.setDiscarded(MemtableAllocator.java:93)
at
org.apache.cassandra.utils.memory.SlabAllocator.setDiscarded(SlabAllocator.java:120)
at org.apache.cassandra.db.Memtable.setDiscarded(Memtable.java:201)
at
org.apache.cassandra.db.ColumnFamilyStore$Flush$1.runMayThrow(ColumnFamilyStore.java:1216)
at
org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:829)
Dec 19, 2022 @ 13:07:15.551MemtablePostFlush:2626
org.apache.cassandra.db.commitlog.AbstractCommitLogSegmentManager
archiveAndDiscard - Segment
CommitLogSegment(/data/cassandra/commitlog/CommitLog-7-1670343439312.log) is no
longer active and will be deleted now
Dec 19, 2022 @ 13:07:15.551MemtablePostFlush:2626
org.apache.cassandra.db.commitlog.CommitLog discardCompletedSegments - Commit
log segment
CommitLogSegment(/data/cassandra/commitlog/CommitLog-7-1670343439312.log) is
unused
Dec 19, 2022 @ 13:07:15.551CompactionExecutor:6104
org.apache.cassandra.db.compaction.TimeWindowCompactionStrategy newestBucket -
bucket size 2 >= 2 and not in current bucket, compacting what's here:
[BigTableReader(path='/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-27-big-Data.db'),
BigTableReader(path='/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-26-big-Data.db')]
Dec 19, 2022 @ 13:07:15.551CompactionExecutor:6104
org.apache.cassandra.db.compaction.CompactionTask runMayThrow - Compacting
(ad77aef0-7f95-11ed-bab7-e7d7c3e60f28)
[/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-27-big-Data.db:level=0,
/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-26-big-Data.db:level=0,
]
Dec 19, 2022 @ 13:07:15.550MemtableFlushWriter:3385
org.apache.cassandra.db.ColumnFamilyStore flushMemtable - Flushed to
[BigTableReader(path='/data/cassandra/data/system_distributed/parent_repair_history-deabd734b99d3b9c92e5fd92eb5abf14/nb-31-big-Data.db')]
(1 sstables, 7.193KiB), biggest 7.193KiB, smallest 7.193KiB
Dec 19, 2022 @ 13:07:15.550MemtableFlushWriter:3384
org.apache.cassandra.db.ColumnFamilyStore flushMemtable - Flushed to
[BigTableReader(path='/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-28-big-Data.db')]
(1 sstables, 6.510KiB), biggest 6.510KiB, smallest 6.510KiB
Dec 19, 2022 @ 13:07:15.546PerDiskMemtableFlushWriter_0:3385
org.apache.cassandra.db.Memtable writeSortedContents - Completed flushing
/data/cassandra/data/system_distributed/parent_repair_history-deabd734b99d3b9c92e5fd92eb5abf14/nb-31-big-Data.db
(4.170KiB) for commitlog position CommitLogPosition(segmentId=1670343439574,
position=3282)
Dec 19, 2022 @ 13:07:15.545PerDiskMemtableFlushWriter_0:3384
org.apache.cassandra.db.Memtable writeSortedContents - Completed flushing
/data/cassandra/data/system_distributed/repair_history-759fffad624b318180eefa9a52d1f627/nb-28-big-Data.db
(1.785KiB) for commitlog position CommitLogPosition(segmentId=1670343439574,
position=1779)
Dec 19, 2022 @ 13:07:15.545PerDiskMemtableFlushWriter_0:3384
org.apache.cassandra.db.Memtable writeSortedContents - Writing
Memtable-repair_history@685478737(-8.285KiB serialized bytes, 246 ops, -0%/0%
of on/off-heap limit), flushed range = (min(-9223372036854775808),
max(9223372036854775807)]Dec 19, 2022 @
13:07:15.545PerDiskMemtableFlushWriter_0:3385 org.apache.cassandra.db.Memtable
writeSortedContents - Writing Memtable-parent_repair_history@860004687(5.211KiB
serialized bytes, 2 ops, 0%/0% of on/off-heap limit), flushed range =
(min(-9223372036854775808), max(9223372036854775807)]Dec 19, 2022 @
13:07:15.543COMMIT-LOG-ALLOCATOR org.apache.cassandra.db.ColumnFamilyStore
logFlush - Enqueuing flush of parent_repair_history: 14.763KiB (0%) on-heap,
0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:07:15.542COMMIT-LOG-ALLOCATOR
org.apache.cassandra.db.ColumnFamilyStore logFlush - Enqueuing flush of
repair_history: -8.000KiB (-0%) on-heap, 0.000KiB (0%) off-heap
Dec 19, 2022 @ 13:06:22.905ReadStage-1
org.apache.cassandra.utils.memory.BufferPool log - Maximum memory usage reached
(512.000MiB), cannot allocate chunk of 8.000MiB
Dec 19, 2022 @ 13:05:36.979NonPeriodicTasks:1
org.apache.cassandra.io.sstable.SSTable delete - Deleting sstable:
/data/cassandra/data/X/Y-48b97b403c1011eab0e9f58b98b870bd/nb-2963-big
Dec 19, 2022 @ 13:05:36.979CompactionExecutor:6105
org.apache.cassandra.db.compaction.CompactionTask runMayThrow - Compacted
(72b6a320-7f95-11ed-bab7-e7d7c3e60f28) 1 sstables to [] to level=0. 0.000KiB
to 0.000KiB (~0% of original) in 1ms. Read Throughput = 0.000KiB/s, Write
Throughput = 0.000KiB/s, Row Throughput = ~0/s. 0 total partitions merged to
0. Partition merge counts were {}
{code}
was (Author: nicolas.henneaux):
Thanks for your feedback, of course I can provide more details.
1. There is no secondary index in use.
2. Not sure what is really heavy but I don't believe it is heavy, each node has
~200GB of data with ttl of 10 days for most of the data (~20GB written by day).
About overwrite, I guess you mean updating some cells, yes we usually insert
then update a row within a short time frame (~10min).
3. I don't think off-heap is used. If disabled by default, that's not something
I enabled
> AssertionError on thread MemtableReclaimMemory in
> MemtablePool$SubPool.released(MemtablePool.java:193)
> ------------------------------------------------------------------------------------------------------
>
> Key: CASSANDRA-18125
> URL: https://issues.apache.org/jira/browse/CASSANDRA-18125
> Project: Cassandra
> Issue Type: Bug
> Reporter: Nicolas Henneaux
> Priority: Normal
>
> On two nodes (on a 5 nodes cluster) on the cluster I'm running, I got the
> following exception. It occurred at 3,5 minutes interval.
> {code}
> MemtableReclaimMemory:2625 org.apache.cassandra.service.CassandraDaemon
> uncaughtException - Exception in thread
> Thread[MemtableReclaimMemory:2625,5,main]java.lang.AssertionError: null
> at
> org.apache.cassandra.utils.memory.MemtablePool$SubPool.released(MemtablePool.java:193)
> at
> org.apache.cassandra.utils.memory.MemtableAllocator$SubAllocator.releaseAll(MemtableAllocator.java:151)
> at
> org.apache.cassandra.utils.memory.MemtableAllocator$SubAllocator.setDiscarded(MemtableAllocator.java:142)
> at
> org.apache.cassandra.utils.memory.MemtableAllocator.setDiscarded(MemtableAllocator.java:93)
> at
> org.apache.cassandra.utils.memory.SlabAllocator.setDiscarded(SlabAllocator.java:120)
> at org.apache.cassandra.db.Memtable.setDiscarded(Memtable.java:201)
> at
> org.apache.cassandra.db.ColumnFamilyStore$Flush$1.runMayThrow(ColumnFamilyStore.java:1216)
> at
> org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
> at
> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at
> io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.base/java.lang.Thread.run(Thread.java:829)
> {code}
> {code}
> $ nodetool info
> ID :
> Gossip active : true
> Native Transport active: true
> Load : 204.67 GiB
> Generation No : 1670343179
> Uptime (seconds) : 1110514
> Heap Memory (MB) : 7218.07 / 24576.00
> Off Heap Memory (MB) : 784.06
> Data Center : par
> Rack : e1
> Exceptions : 1
> Key Cache : entries 802712, size 100 MiB, capacity 100 MiB,
> 774541004 hits, 914207516 requests, 0.847 recent hit rate, 14400 save period
> in seconds
> Row Cache : entries 0, size 0 bytes, capacity 0 bytes, 0 hits, 0
> requests, NaN recent hit rate, 0 save period in seconds
> Counter Cache : entries 0, size 0 bytes, capacity 50 MiB, 0 hits, 0
> requests, NaN recent hit rate, 7200 save period in seconds
> Percent Repaired : 2.3272298419424144E-5%
> Token : (invoke with -T/--tokens to see all 8 tokens)
> $ java -version
> openjdk version "11.0.16" 2022-07-19 LTS
> OpenJDK Runtime Environment (Red_Hat-11.0.16.0.8-1.el7_9) (build
> 11.0.16+8-LTS)
> OpenJDK 64-Bit Server VM (Red_Hat-11.0.16.0.8-1.el7_9) (build 11.0.16+8-LTS,
> mixed mode, sharing)
> $ nodetool version
> ReleaseVersion: 4.0.6
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscr...@cassandra.apache.org
For additional commands, e-mail: commits-h...@cassandra.apache.org
