cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Dathan Pattishall <datha...@gmail.com>
Subject Memtable adjusting impact expectations?
Date Wed, 15 Sep 2010 01:33:04 GMT
Okay from what I gather. When data is written its always written to memory.
The flow for our concerns is the data is written to the commitLog then to
the memtable.

If any of memtable's 3 tunable thresholds are hit a flush occurs writing the
data sorted by key to the SSTABLE still enabling sequential disk access. The
fastest disk access is sequential while random is the slowest - this is just
a statement to make sure people are on the same page.

Now the data in the SSTABLE is immutable, and when the SSTABLE threshold is
hit (4 by default) the multiple SSTABLES are turned into a single TABLE,
this is compaction. Now I can't verify this because I never see more then 1
SSTABLE at a time, which could just be me misinterpreting the info. This
Operation singly should produce the most load.

Using JCONSOLE connected to a live Cass box JMX port and forced operations
from the MBEANS tab. I've quantified that normal operations for my
environment  is 3% CPU utilization.
Each Node roughly does 200 operations per second on a standard key/value
pair sorted by UTF8 with a Random Partitioner.

Doing a Flush for this 10MB Memtable consumes 33% of my CPU from Java's
point of view and that 33% is sustained for 15 mins - I assume some sorting
needs to be done according to this link:
http://wiki.apache.org/cassandra/JmxInterface#org.apache.cassandra.concurrent.FLUSH-WRITER-POOL

Doing a compaction consumes 30% of my CPU and lasts for 10 mins from the
subsequent flush.

Now to give some context my MemtableDataSize was around 11,000,000. I am
going to assume that this is in units of bytes so roughly 10MB of data. Is
assuming that MemtableDataSize is in units of bytes correct? If so why does
it take 15 mins to flush 10MB of data to a RAID-10 8 15K RPM disk array with
a 256 MB of memory and BBC on a dedicated hardware controller?

Additional to this I see in system.log

WARN [MESSAGE-DESERIALIZER-POOL:1] 2010-08-26 08:27:11,541
MessageDeserializationTask.java (line 47) dropping message (9,713ms past
timeout)

39,625 events are showing. How do I get rid of this? If its a warning and is
dropping messages how can I fix the warning?



So, in summary. On Cassandra 0.6.4
with
TotalDiskSpaceUsed - 40GB
MemtableDataSize - 10MB
MemtableColumnsCount 130K

How do I remove MessageDeserializationTasks warnings?
How do I reduce the compaction time?
Why is flushing taking so long?
What do I look at to tune Memtable thresholds, because this
http://wiki.apache.org/cassandra/MemtableThresholds does not help, and I
believe that I'm not in a position where I need to tune the defaults.

http://www.riptano.com/blog/cassandra-annotated-changelog-063 allows me to
lower the priority of compaction, but to get the best compaction times
verses system load how do I tune for that?



Below is some sample output of system.log

Notice that SSTable 1155 is 320 MB, is the sorting taking all the time?
Because 320MB written even randomly should be very fast. 320 MB written
sequentially takes 2 seconds, while randomly I would expect 9 seconds. (320
MB/34 MB/sec random writes == 9 seconds)


 INFO [COMPACTION-POOL:1] 2010-09-14 20:40:39,120 CompactionManager.java
(line 320) Compacted to
/data/cassandra/data/TimeFrameClicks/Standard2-1155-Data.db.
339681221/339679627 bytes for 1253279 keys.  Time: 18645ms.
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 21:14:49,518
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1154-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 21:14:49,547
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1152-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 21:14:49,574
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1153-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 21:14:49,603
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1151-Data.db
 INFO [ROW-MUTATION-STAGE:6] 2010-09-14 22:24:33,320 ColumnFamilyStore.java
(line 357) Standard2 has reached its threshold; switching in a fresh
Memtable at
CommitLogContext(file='/data/cassandra/commitlog/CommitLog-1284496449043.log',
position=68512986)
 INFO [ROW-MUTATION-STAGE:6] 2010-09-14 22:24:33,320 ColumnFamilyStore.java
(line 609) Enqueuing flush of Memtable-Standard2@798596883(11324628 bytes,
314573 operations)
 INFO [FLUSH-WRITER-POOL:1] 2010-09-14 22:24:33,321 Memtable.java (line 148)
Writing Memtable-Standard2@798596883(11324628 bytes, 314573 operations)
 INFO [FLUSH-WRITER-POOL:1] 2010-09-14 22:24:38,974 Memtable.java (line 162)
Completed flushing
/data/cassandra/data/TimeFrameClicks/Standard2-1156-Data.db
 INFO [COMPACTION-POOL:1] 2010-09-14 22:25:19,326 CompactionManager.java
(line 246) Compacting
[org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1156-Data.db'),org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1129-Data.db'),org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1150-Data.db'),org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1108-Data.db'),org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1023-Data.db'),org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1155-Data.db')]
 INFO [GC inspection] 2010-09-14 22:25:21,236 GCInspector.java (line 116) GC
for ConcurrentMarkSweep: 1825 ms, 650770408 reclaimed leaving 472796832
used; max is 7645888512
 INFO [GC inspection] 2010-09-14 22:25:21,237 GCInspector.java (line 137)
Pool Name                    Active   Pending
 INFO [GC inspection] 2010-09-14 22:25:21,238 GCInspector.java (line 143)
STREAM-STAGE                      0         0
 INFO [GC inspection] 2010-09-14 22:25:21,238 GCInspector.java (line 143)
FILEUTILS-DELETE-POOL             0         0
 INFO [GC inspection] 2010-09-14 22:25:21,238 GCInspector.java (line 143)
RESPONSE-STAGE                    0         0
 INFO [GC inspection] 2010-09-14 22:25:21,239 GCInspector.java (line 143)
ROW-READ-STAGE                    1         5
 INFO [GC inspection] 2010-09-14 22:25:21,239 GCInspector.java (line 143)
LB-OPERATIONS                     0         0
 INFO [GC inspection] 2010-09-14 22:25:21,239 GCInspector.java (line 143)
GMFD                              0         3*
 INFO [GC inspection] 2010-09-14 22:25:21,240 GCInspector.java (line 143)
MESSAGE-DESERIALIZER-POOL         0       121*
 INFO [GC inspection] 2010-09-14 22:25:21,240 GCInspector.java (line 143)
CONSISTENCY-MANAGER               0         7
 INFO [GC inspection] 2010-09-14 22:25:21,240 GCInspector.java (line 143)
LB-TARGET                         0         0
 INFO [GC inspection] 2010-09-14 22:25:21,240 GCInspector.java (line 143)
ROW-MUTATION-STAGE                0         0
 INFO [GC inspection] 2010-09-14 22:25:21,241 GCInspector.java (line 143)
MESSAGE-STREAMING-POOL            0         0
 INFO [GC inspection] 2010-09-14 22:25:21,241 GCInspector.java (line 143)
LOAD-BALANCER-STAGE               0         0
 INFO [GC inspection] 2010-09-14 22:25:21,241 GCInspector.java (line 143)
FLUSH-SORTER-POOL                 0         0
 INFO [GC inspection] 2010-09-14 22:25:21,242 GCInspector.java (line 143)
MEMTABLE-POST-FLUSHER             0         0
 INFO [GC inspection] 2010-09-14 22:25:21,242 GCInspector.java (line 143)
AE-SERVICE-STAGE                  0         0
 INFO [GC inspection] 2010-09-14 22:25:21,243 GCInspector.java (line 143)
FLUSH-WRITER-POOL                 0         0
 INFO [GC inspection] 2010-09-14 22:25:21,243 GCInspector.java (line 143)
HINTED-HANDOFF-POOL               0         0
 INFO [GC inspection] 2010-09-14 22:25:21,244 GCInspector.java (line 148)
CompactionManager               n/a         0
 *INFO [COMPACTION-POOL:1] 2010-09-14 22:38:13,035 CompactionManager.java
(line 320) Compacted to
/data/cassandra/data/TimeFrameClicks/Standard2-1157-Data.db.
13065811194/8886372187 bytes for 32990587 keys.  Time: 773708ms.
 INFO [COMPACTION-POOL:1] 2010-09-14 22:40:23,776 CompactionManager.java
(line 246) Compacting
[org.apache.cassandra.io.SSTableReader(path='/data/cassandra/data/TimeFrameClicks/Standard2-1157-Data.db')]
 INFO [COMPACTION-POOL:1] 2010-09-14 22:54:20,197 CompactionManager.java
(line 320) Compacted to
/data/cassandra/data/TimeFrameClicks/Standard2-1158-Data.db.
8886372187/8886372187 bytes for 32990587 keys.  Time: 836420ms.*
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:26:54,242
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1157-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:26:54,422
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1156-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:26:56,137
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1129-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:26:59,458
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1108-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:27:01,106
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1150-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:27:12,050
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1023-Data.db
 INFO [SSTABLE-CLEANUP-TIMER] 2010-09-14 23:27:12,534
SSTableDeletingReference.java (line 104) Deleted
/data/cassandra/data/TimeFrameClicks/Standard2-1155-Data.db

Mime
View raw message