cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Spacejatsi <spaceja...@gmail.com>
Subject Re: Inserting files to Cassandra timeouts
Date Fri, 30 Apr 2010 08:04:57 GMT
I ran again the test, inserting 64 files (15-25MB per file) with 2 threads inserting file file
at the time. 
First 30 files goes relatively fast in, but then it jams, and finally timeouts. This tpstats
is taken when the first timeout came.

I also tested to split the files max of 5 mb per file. That was running fine about 50% but
that also jammed. 
Should I be running the inserts to multiple nodes at the same time, not to overload one node
only?

100305-mac17:bin jussi.pori$ ./nodetool -host localhost tpstats
Pool Name                    Active   Pending      Completed
FILEUTILS-DELETE-POOL             0         0              8
STREAM-STAGE                      0         0              0
RESPONSE-STAGE                    0         0              0
ROW-READ-STAGE                    0         0              0
LB-OPERATIONS                     0         0              0
MESSAGE-DESERIALIZER-POOL         0         0              0
GMFD                              0         0              0
LB-TARGET                         0         0              0
CONSISTENCY-MANAGER               0         0              0
ROW-MUTATION-STAGE                2         2             31
MESSAGE-STREAMING-POOL            0         0              0
LOAD-BALANCER-STAGE               0         0              0
FLUSH-SORTER-POOL                 0         0              0
MEMTABLE-POST-FLUSHER             0         0              5
FLUSH-WRITER-POOL                 0         0              5
AE-SERVICE-STAGE                  0         0              0

This is the system.log from that test:

 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:34,174 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613414173.log
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:35,481 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613415481.log
 INFO [ROW-MUTATION-STAGE:9] 2010-04-30 10:43:36,106 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613415481.log',
position=18000316)
 INFO [ROW-MUTATION-STAGE:9] 2010-04-30 10:43:36,107 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@505410915
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:43:36,108 Memtable.java (line 148) Writing Memtable(Standard1)@505410915
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:36,862 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613416862.log
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:39,624 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613419624.log
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:42,555 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613422555.log
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:43:42,603 Memtable.java (line 162) Completed flushing
/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-1-Data.db
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:42,650 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613414173.log)
 INFO [ROW-MUTATION-STAGE:15] 2010-04-30 10:43:42,655 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613422555.log',
position=145)
 INFO [ROW-MUTATION-STAGE:15] 2010-04-30 10:43:42,656 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@481059370
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:43:42,657 Memtable.java (line 148) Writing Memtable(Standard1)@481059370
 INFO [GC inspection] 2010-04-30 10:43:49,760 GCInspector.java (line 110) GC for ParNew: 2390
ms, 58993544 reclaimed leaving 614178960 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:43:49,913 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613429913.log
 INFO [GC inspection] 2010-04-30 10:44:07,039 GCInspector.java (line 110) GC for ParNew: 13666
ms, 60792648 reclaimed leaving 816424624 used; max is 4108386304
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:44:07,040 Memtable.java (line 162) Completed flushing
/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-2-Data.db
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:44:08,164 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613415481.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:44:08,164 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613416862.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:44:08,169 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613419624.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:44:10,256 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613450256.log
 INFO [ROW-MUTATION-STAGE:21] 2010-04-30 10:44:10,564 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613450256.log',
position=6000316)
 INFO [ROW-MUTATION-STAGE:21] 2010-04-30 10:44:10,565 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@1457398981
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:44:10,565 Memtable.java (line 148) Writing Memtable(Standard1)@1457398981
 INFO [GC inspection] 2010-04-30 10:44:19,393 GCInspector.java (line 110) GC for ParNew: 8633
ms, 56607240 reclaimed leaving 930530096 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:45:02,527 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613502527.log
 INFO [GC inspection] 2010-04-30 10:45:58,307 GCInspector.java (line 110) GC for ParNew: 49727
ms, 76431056 reclaimed leaving 1102511632 used; max is 4108386304
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:47:05,944 Memtable.java (line 162) Completed flushing
/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-3-Data.db
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:47:14,264 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613634264.log
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:48:23,571 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613422555.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:48:23,599 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613429913.log)
 INFO [ROW-MUTATION-STAGE:26] 2010-04-30 10:48:24,348 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613634264.log',
position=18000316)
 INFO [ROW-MUTATION-STAGE:26] 2010-04-30 10:48:24,409 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@47327328
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:48:24,409 Memtable.java (line 148) Writing Memtable(Standard1)@47327328
 INFO [GC inspection] 2010-04-30 10:49:27,238 GCInspector.java (line 110) GC for ParNew: 44522
ms, 80667552 reclaimed leaving 1234718736 used; max is 4108386304
 INFO [GC inspection] 2010-04-30 10:50:53,913 GCInspector.java (line 110) GC for ParNew: 73534
ms, 83052224 reclaimed leaving 1414752304 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:51:19,800 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613879800.log
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:52:17,371 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613937371.log
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:52:18,731 Memtable.java (line 162) Completed flushing
/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-4-Data.db
 INFO [COMPACTION-POOL:1] 2010-04-30 10:52:18,880 CompactionManager.java (line 246) Compacting
[org.apache.cassandra.io.SSTableReader(path='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-1-Data.db'),org.apache.cassandra.io.SSTableReader(path='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-2-Data.db'),org.apache.cassandra.io.SSTableReader(path='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-3-Data.db'),org.apache.cassandra.io.SSTableReader(path='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-4-Data.db')]
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:52:32,070 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613450256.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:52:32,188 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613502527.log)


 INFO [GC inspection] 2010-04-30 10:53:46,949 GCInspector.java (line 110) GC for ParNew: 13621
ms, 88262512 reclaimed leaving 1581477264 used; max is 4108386304
 INFO [GC inspection] 2010-04-30 10:55:08,644 GCInspector.java (line 110) GC for ParNew: 15073
ms, 20452712 reclaimed leaving 431259232 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:55:08,644 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614108644.log
 INFO [ROW-MUTATION-STAGE:32] 2010-04-30 10:55:12,952 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614108644.log',
position=18000316)
 INFO [ROW-MUTATION-STAGE:32] 2010-04-30 10:55:12,953 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@1990541648
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:55:12,967 Memtable.java (line 148) Writing Memtable(Standard1)@1990541648
 INFO [GC inspection] 2010-04-30 10:55:20,718 GCInspector.java (line 110) GC for ParNew: 6685
ms, 31187112 reclaimed leaving 626981312 used; max is 4108386304
 INFO [GC inspection] 2010-04-30 10:55:31,084 GCInspector.java (line 110) GC for ParNew: 10109
ms, 3237800 reclaimed leaving 752990680 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:55:33,247 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614133247.log
 INFO [GC inspection] 2010-04-30 10:55:41,083 GCInspector.java (line 110) GC for ParNew: 1426
ms, 48780568 reclaimed leaving 1053980248 used; max is 4108386304
 INFO [GC inspection] 2010-04-30 10:56:01,084 GCInspector.java (line 110) GC for ParNew: 269
ms, 200003712 reclaimed leaving 1500784512 used; max is 4108386304
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:56:03,609 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614163609.log
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:56:13,219 Memtable.java (line 162) Completed flushing
/Users/jussi.pori/Programs/apache-cassandra-0.6.1/data/Clutters/Standard1-5-Data.db
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:56:13,405 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613634264.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:56:13,406 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613879800.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:56:13,407 CommitLog.java (line 407) Discarding obsolete
commit log:CommitLogSegment(/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272613937371.log)
 INFO [COMMIT-LOG-WRITER] 2010-04-30 10:56:20,275 CommitLogSegment.java (line 50) Creating
new commitlog segment /Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614180275.log
 INFO [ROW-MUTATION-STAGE:6] 2010-04-30 10:56:20,300 ColumnFamilyStore.java (line 357) Standard1
has reached its threshold; switching in a fresh Memtable at CommitLogContext(file='/Users/jussi.pori/Programs/apache-cassandra-0.6.1/commitlog/CommitLog-1272614180275.log',
position=145)
 INFO [ROW-MUTATION-STAGE:6] 2010-04-30 10:56:20,300 ColumnFamilyStore.java (line 609) Enqueuing
flush of Memtable(Standard1)@1034225086
 INFO [FLUSH-WRITER-POOL:1] 2010-04-30 10:56:20,301 Memtable.java (line 148) Writing Memtable(Standard1)@1034225086
 INFO [GC inspection] 2010-04-30 10:56:42,053 GCInspector.java (line 110) GC for ParNew: 21602
ms, 58548344 reclaimed leaving 1670216000 used; max is 4108386304
 INFO [GC inspection] 2010-04-30 10:57:12,785 GCInspector.java (line 110) GC for ParNew: 30465
ms, 3229848 reclaimed leaving 1922229272 used; max is 4108386304


On Apr 29, 2010, at 3:50 PM, Jonathan Ellis wrote:

> are you seeing memtable flushes and compactions in the log?
> 
> what does tpstats look like when it's timing out?
> 
> spending 2000ms on GC every 50s indicates that it's not GC causing
> your problem.  (especially when all of them are ParNew, which are
> completely non-blocking to other threads)
> 
> On Wed, Apr 28, 2010 at 9:24 AM, Jussi P?├Âri
> <jussi@androidconsulting.com> wrote:
>> new try, previous went to wrong place...
>> 
>> Hi all,
>> 
>> i'm trying to run a scenario of adding files from specific folder to cassandra. Now
I have 64 files(about 15-20 MB per file) and overall of 1GB of data.
>> I'm able to insert a round 40 files, but after that the cassandra goes to some GC
loop and I finally get an timeout to the client.
>> It is not going to OOM, but it just jams.
>> 
>> Here is what I had last marks in log file:
>> NFO [GC inspection] 2010-04-28 10:07:55,297 GCInspector.java (line 110) GC for ParNew:
232 ms, 25731128 reclaimed leaving 553241120 used; max is 4108386304
>>  INFO [GC inspection] 2010-04-28 10:09:02,331 GCInspector.java (line 110) GC for
ParNew: 2844 ms, 238909856 reclaimed leaving 1435582832 used; max is 4108386304
>>  INFO [GC inspection] 2010-04-28 10:09:49,421 GCInspector.java (line 110) GC for
ParNew: 30666 ms, 11185824 reclaimed leaving 1679795336 used; max is 4108386304
>>  INFO [GC inspection] 2010-04-28 10:11:18,090 GCInspector.java (line 110) GC for
ParNew: 895 ms, 17921680 reclaimed leaving 1589308456 used; max is 4108386304
>> 
>> 
>> 
>> I think that I must have something wrong in my configurations or in how I use cassandra,
because here people are inserting 10 times more stuff and it works.
>> 
>> Column family I using:
>> <ColumnFamily CompareWith="BytesType" Name="Standard1"/>
>> Basically inserting with key name is "Folder_name" and column name is "file name"
and value is the file content.
>> I tried with Hector(mainly) and directly using thrift(insert and batch_mutate).
>> 
>> In my case, the data does not need to readable immediately after insert, but I don't
know it that helps in anyway.
>> 
>> 
>> My environment :
>> mac and/or linux, tested in both
>> java 1.6.0_17
>> Cassandra 0.6.1
>> 
>> 
>> 
>>  <RpcTimeoutInMillis>60000</RpcTimeoutInMillis>
>> <CommitLogRotationThresholdInMB>32</CommitLogRotationThresholdInMB>
>> <RowWarningThresholdInMB>512</RowWarningThresholdInMB>
>>  <SlicedBufferSizeInKB>32</SlicedBufferSizeInKB>
>>  <FlushDataBufferSizeInMB>32</FlushDataBufferSizeInMB>
>>  <FlushIndexBufferSizeInMB>8</FlushIndexBufferSizeInMB>
>>  <ColumnIndexSizeInKB>64</ColumnIndexSizeInKB>
>>  <MemtableThroughputInMB>64</MemtableThroughputInMB>
>>  <BinaryMemtableThroughputInMB>256</BinaryMemtableThroughputInMB>
>>  <MemtableOperationsInMillions>0.1</MemtableOperationsInMillions>
>>  <MemtableFlushAfterMinutes>60</MemtableFlushAfterMinutes>
>>  <ConcurrentReads>8</ConcurrentReads>
>>  <ConcurrentWrites>32</ConcurrentWrites>
>>  <CommitLogSync>batch</CommitLogSync>
>>  <!-- CommitLogSyncPeriodInMS>10000</CommitLogSyncPeriodInMS -->
>>  <CommitLogSyncBatchWindowInMS>1.0</CommitLogSyncBatchWindowInMS>
>>  <GCGraceSeconds>500</GCGraceSeconds>
>> 
>> JVM_OPTS=" \
>>        -server \
>>        -Xms3G \
>>        -Xmx3G \
>>        -XX:PermSize=512m \
>>        -XX:MaxPermSize=800m \
>>        -XX:MaxNewSize=256m \
>>        -XX:NewSize=128m \
>>        -XX:TargetSurvivorRatio=90 \
>>        -XX:+AggressiveOpts \
>>        -XX:+UseParNewGC \
>>        -XX:+UseConcMarkSweepGC \
>>        -XX:+CMSParallelRemarkEnabled \
>>        -XX:+HeapDumpOnOutOfMemoryError \
>>        -XX:SurvivorRatio=128 \
>>        -XX:MaxTenuringThreshold=0 \
>>        -XX:+DisableExplicitGC \
>>        -Dcom.sun.management.jmxremote.port=8080 \
>>        -Dcom.sun.management.jmxremote.ssl=false \
>>        -Dcom.sun.management.jmxremote.authenticate=false"
>> 
>> 
> 
> 
> 
> -- 
> Jonathan Ellis
> Project Chair, Apache Cassandra
> co-founder of Riptano, the source for professional Cassandra support
> http://riptano.com


Mime
View raw message