You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Jason Tang <ar...@gmail.com> on 2012/06/17 14:16:43 UTC
GCInspector works every 10 seconds!
Hi
After running load testing for 24 hours(insert, update and delete), now
no new traffic to Cassandra, but Cassnadra shows still have high load(CPU
usage), from the system.log, it shows it always perform GC. I don't know
why it work as that, seems memory is not low.
Here is some configuration and log, where I can find the clue why Cassandra
works as this?
cassandra.yaml
disk_access_mode: mmap_index_only
# /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 tpstats
Pool Name Active Pending Completed Blocked All
time blocked
ReadStage 0 0 45387558 0
0
RequestResponseStage 0 0 96568347 0
0
MutationStage 0 0 60215102 0
0
ReadRepairStage 0 0 0
0 0
ReplicateOnWriteStage 0 0 0 0
0
GossipStage 0 0 399012
0 0
AntiEntropyStage 0 0 0
0 0
MigrationStage 0 0 30
0 0
MemtablePostFlusher 0 0 279 0
0
StreamStage 0 0 0
0 0
FlushWriter 0 0 1846
0 1052
MiscStage 0 0 0
0 0
InternalResponseStage 0 0 0 0
0
HintedHandoff 0 0 5
0 0
Message type Dropped
RANGE_SLICE 0
READ_REPAIR 0
BINARY 0
READ 1
MUTATION 1390
REQUEST_RESPONSE 0
# /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 info
Token : 56713727820156410577229101238628035242
Gossip active : true
Load : 37.57 GB
Generation No : 1339813956
Uptime (seconds) : 120556
Heap Memory (MB) : 3261.14 / 5984.00
Data Center : datacenter1
Rack : rack1
Exceptions : 0
INFO [ScheduledTasks:1] 2012-06-17 19:47:36,633 GCInspector.java (line
123) GC for ParNew: 222 ms for 1 collections, 2046077640 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:48:41,714 GCInspector.java (line
123) GC for ParNew: 262 ms for 1 collections, 2228128408 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:48:49,717 GCInspector.java (line
123) GC for ParNew: 237 ms for 1 collections, 2390412728 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:48:57,719 GCInspector.java (line
123) GC for ParNew: 223 ms for 1 collections, 2508702896 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:50:01,988 GCInspector.java (line
123) GC for ParNew: 232 ms for 1 collections, 2864574832 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:50:10,075 GCInspector.java (line
123) GC for ParNew: 208 ms for 1 collections, 2964629856 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:50:21,078 GCInspector.java (line
123) GC for ParNew: 258 ms for 1 collections, 3149127368 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:51:26,095 GCInspector.java (line
123) GC for ParNew: 213 ms for 1 collections, 3421495400 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:51:34,097 GCInspector.java (line
123) GC for ParNew: 218 ms for 1 collections, 3543978312 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:52:37,229 GCInspector.java (line
123) GC for ParNew: 221 ms for 1 collections, 3752290000 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:52:37,230 GCInspector.java (line
123) GC for ConcurrentMarkSweep: 206 ms for 1 collections, 3752313400 used;
max is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:52:46,507 GCInspector.java (line
123) GC for ParNew: 243 ms for 1 collections, 3663162192 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:52:54,510 GCInspector.java (line
123) GC for ParNew: 283 ms for 1 collections, 1582282248 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:54:01,704 GCInspector.java (line
123) GC for ParNew: 235 ms for 1 collections, 1935534800 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:55:13,747 GCInspector.java (line
123) GC for ParNew: 233 ms for 1 collections, 2356975504 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:55:21,749 GCInspector.java (line
123) GC for ParNew: 264 ms for 1 collections, 2530976328 used; max
is 6274678784
INFO [ScheduledTasks:1] 2012-06-17 19:55:29,794 GCInspector.java (line
123) GC for ParNew: 224 ms for 1 collections, 2592311336 used; max
is 6274678784
BRs
//Ares
Re: GCInspector works every 10 seconds!
Posted by Rob Coli <rc...@palominodb.com>.
On Mon, Jun 18, 2012 at 12:07 AM, Jason Tang <ar...@gmail.com> wrote:
> After I enable key cache and row cache, the problem gone, I guess it because
> we have lots of data in SSTable, and it takes more time, memory and cpu to
> search the data.
The Key Cache is usually a win if added like this. The Row cache is
less likely to be. If I were you I would check your row cache hit
rates to make sure you are actually getting win. :)
=Rob
--
=Robert Coli
AIM>ALK - rcoli@palominodb.com
YAHOO - rcoli.palominob
SKYPE - rcoli_palominodb
Re: GCInspector works every 10 seconds!
Posted by Jason Tang <ar...@gmail.com>.
Hi
After I enable key cache and row cache, the problem gone, I guess it
because we have lots of data in SSTable, and it takes more time, memory and
cpu to search the data.
BRs
//Tang Weiqiang
2012/6/18 aaron morton <aa...@thelastpickle.com>
> It is also strange that although no data in Cassandra can fulfill the
> query conditions, but it takes more time if we have more data in Cassandra.
>
>
> These log messages:
>
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408920e049c22:true:4@1339865451865018
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408a0eeab052a:true:4@1339865451866000
>
> Say that the slice query read columns from the disk that were deleted.
>
> Have you tried your test with a clean (no files on disk) database ?
>
>
> Cheers
>
> -----------------
> Aaron Morton
> Freelance Developer
> @aaronmorton
> http://www.thelastpickle.com
>
> On 18/06/2012, at 12:36 AM, Jason Tang wrote:
>
> Hi
>
> After I change log level to DEBUG, I found some log.
>
> Although we don't have traffic to Cassandra, but we have scheduled the
> task to perform the sliceQuery.
>
> We use time-stamp as the index, we will perform the query by every
> second to check if we have tasks to do.
>
> After 24 hours, we have 40G data in Cassandra, and we configure
> Casssandra as Max JVM Heap 6G, memtable 1G, disk_access_mode:
> mmap_index_only.
>
> It is also strange that although no data in Cassandra can fulfill the
> query conditions, but it takes more time if we have more data in Cassandra.
>
> Because we total have 20 million records in Cassandra which has time
> stamp as the index, and we query by MultigetSubSliceQuery, and set the
> range the value which not match any data in Cassnadra, So it suppose to
> return fast, but as we have 20 million data, it takes 2 seconds to get the
> query result.
>
> Is the GC caused by the scheduled query operation, and why it takes so
> many memory. Could we improve it?
>
> System.log:
> INFO [ScheduledTasks:1] 2012-06-17 20:17:13,574 GCInspector.java (line
> 123) GC for ParNew: 559 ms for 1 collections, 3258240912 used; max
> is 6274678784
> DEBUG [ReadStage:99] 2012-06-17 20:17:25,563 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 00000138ad10358800000137f3372f3e0e28e3b6:false:36@1339815309124015
> DEBUG [ReadStage:99] 2012-06-17 20:17:25,565 ReadVerbHandler.java (line
> 60) Read key 3331; sending response to 158060445@/192.168.0.3
> DEBUG [ReadStage:96] 2012-06-17 20:17:25,845 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 00000138ad10358800000137f33a80cf6cb5d383:false:36@1339815526613007
> DEBUG [ReadStage:96] 2012-06-17 20:17:25,847 ReadVerbHandler.java (line
> 60) Read key 3233; sending response to 158060447@/192.168.0.3
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,952 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 00000138ad10358800000137f330cd70c86690cd:false:36@1339814890872015
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line
> 75) digest is d41d8cd98f00b204e9800998ecf8427e
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line
> 60) Read key 3139; sending response to 158060448@/192.168.0.3
> DEBUG [ReadStage:89] 2012-06-17 20:17:25,959 CollationController.java
> (line 191) collectAllData
> DEBUG [ReadStage:108] 2012-06-17 20:17:25,959 CollationController.java
> (line 191) collectAllData
> DEBUG [ReadStage:107] 2012-06-17 20:17:25,959 CollationController.java
> (line 191) collectAllData
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408920e049c22:true:4@1339865451865018
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408a0eeab052a:true:4@1339865451866000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408b1319577c9:true:4@1339865451867003
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f63408c081e0b8a3:true:4@1339865451867004
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f6340deefb8a0627:true:4@1339865451920001
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f6340df9c21e9979:true:4@1339865451923002
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f6340e095ead1498:true:4@1339865451928000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f6340e1af16cf151:true:4@1339865451935000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line
> 123) collecting 0 of 5000:
> 7fffffffffffffff00000137f6340e396cfdc9fa:true:4@1339865451950000
>
>
> BRs
> //Ares
>
> 2012/6/17 Jason Tang <ar...@gmail.com>
>
>> Hi
>>
>> After running load testing for 24 hours(insert, update and delete),
>> now no new traffic to Cassandra, but Cassnadra shows still have high
>> load(CPU usage), from the system.log, it shows it always perform GC. I
>> don't know why it work as that, seems memory is not low.
>>
>> Here is some configuration and log, where I can find the clue why
>> Cassandra works as this?
>>
>> cassandra.yaml
>> disk_access_mode: mmap_index_only
>>
>> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 tpstats
>> Pool Name Active Pending Completed Blocked
>> All time blocked
>> ReadStage 0 0 45387558
>> 0 0
>> RequestResponseStage 0 0 96568347 0
>> 0
>> MutationStage 0 0 60215102
>> 0 0
>> ReadRepairStage 0 0 0
>> 0 0
>> ReplicateOnWriteStage 0 0 0
>> 0 0
>> GossipStage 0 0 399012
>> 0 0
>> AntiEntropyStage 0 0 0
>> 0 0
>> MigrationStage 0 0 30
>> 0 0
>> MemtablePostFlusher 0 0 279 0
>> 0
>> StreamStage 0 0 0
>> 0 0
>> FlushWriter 0 0 1846
>> 0 1052
>> MiscStage 0 0 0
>> 0 0
>> InternalResponseStage 0 0 0
>> 0 0
>> HintedHandoff 0 0 5
>> 0 0
>>
>> Message type Dropped
>> RANGE_SLICE 0
>> READ_REPAIR 0
>> BINARY 0
>> READ 1
>> MUTATION 1390
>> REQUEST_RESPONSE 0
>>
>>
>> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 info
>> Token : 56713727820156410577229101238628035242
>> Gossip active : true
>> Load : 37.57 GB
>> Generation No : 1339813956
>> Uptime (seconds) : 120556
>> Heap Memory (MB) : 3261.14 / 5984.00
>> Data Center : datacenter1
>> Rack : rack1
>> Exceptions : 0
>>
>>
>> INFO [ScheduledTasks:1] 2012-06-17 19:47:36,633 GCInspector.java (line
>> 123) GC for ParNew: 222 ms for 1 collections, 2046077640 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:48:41,714 GCInspector.java (line
>> 123) GC for ParNew: 262 ms for 1 collections, 2228128408 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:48:49,717 GCInspector.java (line
>> 123) GC for ParNew: 237 ms for 1 collections, 2390412728 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:48:57,719 GCInspector.java (line
>> 123) GC for ParNew: 223 ms for 1 collections, 2508702896 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:50:01,988 GCInspector.java (line
>> 123) GC for ParNew: 232 ms for 1 collections, 2864574832 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:50:10,075 GCInspector.java (line
>> 123) GC for ParNew: 208 ms for 1 collections, 2964629856 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:50:21,078 GCInspector.java (line
>> 123) GC for ParNew: 258 ms for 1 collections, 3149127368 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:51:26,095 GCInspector.java (line
>> 123) GC for ParNew: 213 ms for 1 collections, 3421495400 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:51:34,097 GCInspector.java (line
>> 123) GC for ParNew: 218 ms for 1 collections, 3543978312 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,229 GCInspector.java (line
>> 123) GC for ParNew: 221 ms for 1 collections, 3752290000 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,230 GCInspector.java (line
>> 123) GC for ConcurrentMarkSweep: 206 ms for 1 collections, 3752313400 used;
>> max is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:52:46,507 GCInspector.java (line
>> 123) GC for ParNew: 243 ms for 1 collections, 3663162192 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:52:54,510 GCInspector.java (line
>> 123) GC for ParNew: 283 ms for 1 collections, 1582282248 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:54:01,704 GCInspector.java (line
>> 123) GC for ParNew: 235 ms for 1 collections, 1935534800 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:55:13,747 GCInspector.java (line
>> 123) GC for ParNew: 233 ms for 1 collections, 2356975504 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:55:21,749 GCInspector.java (line
>> 123) GC for ParNew: 264 ms for 1 collections, 2530976328 used; max
>> is 6274678784
>> INFO [ScheduledTasks:1] 2012-06-17 19:55:29,794 GCInspector.java (line
>> 123) GC for ParNew: 224 ms for 1 collections, 2592311336 used; max
>> is 6274678784
>>
>>
>> BRs
>> //Ares
>>
>
>
>
Re: GCInspector works every 10 seconds!
Posted by aaron morton <aa...@thelastpickle.com>.
> It is also strange that although no data in Cassandra can fulfill the query conditions, but it takes more time if we have more data in Cassandra.
These log messages:
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408920e049c22:true:4@1339865451865018
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408a0eeab052a:true:4@1339865451866000
Say that the slice query read columns from the disk that were deleted.
Have you tried your test with a clean (no files on disk) database ?
Cheers
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 18/06/2012, at 12:36 AM, Jason Tang wrote:
> Hi
>
> After I change log level to DEBUG, I found some log.
>
> Although we don't have traffic to Cassandra, but we have scheduled the task to perform the sliceQuery.
>
> We use time-stamp as the index, we will perform the query by every second to check if we have tasks to do.
>
> After 24 hours, we have 40G data in Cassandra, and we configure Casssandra as Max JVM Heap 6G, memtable 1G, disk_access_mode: mmap_index_only.
>
> It is also strange that although no data in Cassandra can fulfill the query conditions, but it takes more time if we have more data in Cassandra.
>
> Because we total have 20 million records in Cassandra which has time stamp as the index, and we query by MultigetSubSliceQuery, and set the range the value which not match any data in Cassnadra, So it suppose to return fast, but as we have 20 million data, it takes 2 seconds to get the query result.
>
> Is the GC caused by the scheduled query operation, and why it takes so many memory. Could we improve it?
>
> System.log:
> INFO [ScheduledTasks:1] 2012-06-17 20:17:13,574 GCInspector.java (line 123) GC for ParNew: 559 ms for 1 collections, 3258240912 used; max
> is 6274678784
> DEBUG [ReadStage:99] 2012-06-17 20:17:25,563 SliceQueryFilter.java (line 123) collecting 0 of 5000: 00000138ad10358800000137f3372f3e0e28e3b6:false:36@1339815309124015
> DEBUG [ReadStage:99] 2012-06-17 20:17:25,565 ReadVerbHandler.java (line 60) Read key 3331; sending response to 158060445@/192.168.0.3
> DEBUG [ReadStage:96] 2012-06-17 20:17:25,845 SliceQueryFilter.java (line 123) collecting 0 of 5000: 00000138ad10358800000137f33a80cf6cb5d383:false:36@1339815526613007
> DEBUG [ReadStage:96] 2012-06-17 20:17:25,847 ReadVerbHandler.java (line 60) Read key 3233; sending response to 158060447@/192.168.0.3
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,952 SliceQueryFilter.java (line 123) collecting 0 of 5000: 00000138ad10358800000137f330cd70c86690cd:false:36@1339814890872015
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line 75) digest is d41d8cd98f00b204e9800998ecf8427e
> DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line 60) Read key 3139; sending response to 158060448@/192.168.0.3
> DEBUG [ReadStage:89] 2012-06-17 20:17:25,959 CollationController.java (line 191) collectAllData
> DEBUG [ReadStage:108] 2012-06-17 20:17:25,959 CollationController.java (line 191) collectAllData
> DEBUG [ReadStage:107] 2012-06-17 20:17:25,959 CollationController.java (line 191) collectAllData
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408920e049c22:true:4@1339865451865018
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408a0eeab052a:true:4@1339865451866000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408b1319577c9:true:4@1339865451867003
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f63408c081e0b8a3:true:4@1339865451867004
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f6340deefb8a0627:true:4@1339865451920001
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f6340df9c21e9979:true:4@1339865451923002
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f6340e095ead1498:true:4@1339865451928000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f6340e1af16cf151:true:4@1339865451935000
> DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fffffffffffffff00000137f6340e396cfdc9fa:true:4@1339865451950000
>
>
> BRs
> //Ares
>
> 2012/6/17 Jason Tang <ar...@gmail.com>
> Hi
>
> After running load testing for 24 hours(insert, update and delete), now no new traffic to Cassandra, but Cassnadra shows still have high load(CPU usage), from the system.log, it shows it always perform GC. I don't know why it work as that, seems memory is not low.
>
> Here is some configuration and log, where I can find the clue why Cassandra works as this?
>
> cassandra.yaml
> disk_access_mode: mmap_index_only
>
> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 tpstats
> Pool Name Active Pending Completed Blocked All time blocked
> ReadStage 0 0 45387558 0 0
> RequestResponseStage 0 0 96568347 0 0
> MutationStage 0 0 60215102 0 0
> ReadRepairStage 0 0 0 0 0
> ReplicateOnWriteStage 0 0 0 0 0
> GossipStage 0 0 399012 0 0
> AntiEntropyStage 0 0 0 0 0
> MigrationStage 0 0 30 0 0
> MemtablePostFlusher 0 0 279 0 0
> StreamStage 0 0 0 0 0
> FlushWriter 0 0 1846 0 1052
> MiscStage 0 0 0 0 0
> InternalResponseStage 0 0 0 0 0
> HintedHandoff 0 0 5 0 0
>
> Message type Dropped
> RANGE_SLICE 0
> READ_REPAIR 0
> BINARY 0
> READ 1
> MUTATION 1390
> REQUEST_RESPONSE 0
>
>
> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 info
> Token : 56713727820156410577229101238628035242
> Gossip active : true
> Load : 37.57 GB
> Generation No : 1339813956
> Uptime (seconds) : 120556
> Heap Memory (MB) : 3261.14 / 5984.00
> Data Center : datacenter1
> Rack : rack1
> Exceptions : 0
>
>
> INFO [ScheduledTasks:1] 2012-06-17 19:47:36,633 GCInspector.java (line 123) GC for ParNew: 222 ms for 1 collections, 2046077640 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:41,714 GCInspector.java (line 123) GC for ParNew: 262 ms for 1 collections, 2228128408 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:49,717 GCInspector.java (line 123) GC for ParNew: 237 ms for 1 collections, 2390412728 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:57,719 GCInspector.java (line 123) GC for ParNew: 223 ms for 1 collections, 2508702896 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:01,988 GCInspector.java (line 123) GC for ParNew: 232 ms for 1 collections, 2864574832 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:10,075 GCInspector.java (line 123) GC for ParNew: 208 ms for 1 collections, 2964629856 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:21,078 GCInspector.java (line 123) GC for ParNew: 258 ms for 1 collections, 3149127368 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:51:26,095 GCInspector.java (line 123) GC for ParNew: 213 ms for 1 collections, 3421495400 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:51:34,097 GCInspector.java (line 123) GC for ParNew: 218 ms for 1 collections, 3543978312 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,229 GCInspector.java (line 123) GC for ParNew: 221 ms for 1 collections, 3752290000 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,230 GCInspector.java (line 123) GC for ConcurrentMarkSweep: 206 ms for 1 collections, 3752313400 used; max is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:46,507 GCInspector.java (line 123) GC for ParNew: 243 ms for 1 collections, 3663162192 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:54,510 GCInspector.java (line 123) GC for ParNew: 283 ms for 1 collections, 1582282248 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:54:01,704 GCInspector.java (line 123) GC for ParNew: 235 ms for 1 collections, 1935534800 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:13,747 GCInspector.java (line 123) GC for ParNew: 233 ms for 1 collections, 2356975504 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:21,749 GCInspector.java (line 123) GC for ParNew: 264 ms for 1 collections, 2530976328 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:29,794 GCInspector.java (line 123) GC for ParNew: 224 ms for 1 collections, 2592311336 used; max
> is 6274678784
>
>
> BRs
> //Ares
>
Re: GCInspector works every 10 seconds!
Posted by Jason Tang <ar...@gmail.com>.
Hi
After I change log level to DEBUG, I found some log.
Although we don't have traffic to Cassandra, but we have scheduled the
task to perform the sliceQuery.
We use time-stamp as the index, we will perform the query by every second
to check if we have tasks to do.
After 24 hours, we have 40G data in Cassandra, and we configure
Casssandra as Max JVM Heap 6G, memtable 1G, disk_access_mode:
mmap_index_only.
It is also strange that although no data in Cassandra can fulfill the
query conditions, but it takes more time if we have more data in Cassandra.
Because we total have 20 million records in Cassandra which has time
stamp as the index, and we query by MultigetSubSliceQuery, and set the
range the value which not match any data in Cassnadra, So it suppose to
return fast, but as we have 20 million data, it takes 2 seconds to get the
query result.
Is the GC caused by the scheduled query operation, and why it takes so
many memory. Could we improve it?
System.log:
INFO [ScheduledTasks:1] 2012-06-17 20:17:13,574 GCInspector.java (line
123) GC for ParNew: 559 ms for 1 collections, 3258240912 used; max
is 6274678784
DEBUG [ReadStage:99] 2012-06-17 20:17:25,563 SliceQueryFilter.java (line
123) collecting 0 of 5000:
00000138ad10358800000137f3372f3e0e28e3b6:false:36@1339815309124015
DEBUG [ReadStage:99] 2012-06-17 20:17:25,565 ReadVerbHandler.java (line 60)
Read key 3331; sending response to 158060445@/192.168.0.3
DEBUG [ReadStage:96] 2012-06-17 20:17:25,845 SliceQueryFilter.java (line
123) collecting 0 of 5000:
00000138ad10358800000137f33a80cf6cb5d383:false:36@1339815526613007
DEBUG [ReadStage:96] 2012-06-17 20:17:25,847 ReadVerbHandler.java (line 60)
Read key 3233; sending response to 158060447@/192.168.0.3
DEBUG [ReadStage:105] 2012-06-17 20:17:25,952 SliceQueryFilter.java (line
123) collecting 0 of 5000:
00000138ad10358800000137f330cd70c86690cd:false:36@1339814890872015
DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line
75) digest is d41d8cd98f00b204e9800998ecf8427e
DEBUG [ReadStage:105] 2012-06-17 20:17:25,953 ReadVerbHandler.java (line
60) Read key 3139; sending response to 158060448@/192.168.0.3
DEBUG [ReadStage:89] 2012-06-17 20:17:25,959 CollationController.java (line
191) collectAllData
DEBUG [ReadStage:108] 2012-06-17 20:17:25,959 CollationController.java
(line 191) collectAllData
DEBUG [ReadStage:107] 2012-06-17 20:17:25,959 CollationController.java
(line 191) collectAllData
DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f63408920e049c22:true:4@1339865451865018
DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f63408a0eeab052a:true:4@1339865451866000
DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f63408b1319577c9:true:4@1339865451867003
DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f63408c081e0b8a3:true:4@1339865451867004
DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f6340deefb8a0627:true:4@1339865451920001
DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f6340df9c21e9979:true:4@1339865451923002
DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f6340e095ead1498:true:4@1339865451928000
DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f6340e1af16cf151:true:4@1339865451935000
DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line
123) collecting 0 of 5000:
7fffffffffffffff00000137f6340e396cfdc9fa:true:4@1339865451950000
BRs
//Ares
2012/6/17 Jason Tang <ar...@gmail.com>
> Hi
>
> After running load testing for 24 hours(insert, update and delete), now
> no new traffic to Cassandra, but Cassnadra shows still have high load(CPU
> usage), from the system.log, it shows it always perform GC. I don't know
> why it work as that, seems memory is not low.
>
> Here is some configuration and log, where I can find the clue why
> Cassandra works as this?
>
> cassandra.yaml
> disk_access_mode: mmap_index_only
>
> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 tpstats
> Pool Name Active Pending Completed Blocked
> All time blocked
> ReadStage 0 0 45387558
> 0 0
> RequestResponseStage 0 0 96568347 0
> 0
> MutationStage 0 0 60215102 0
> 0
> ReadRepairStage 0 0 0
> 0 0
> ReplicateOnWriteStage 0 0 0 0
> 0
> GossipStage 0 0 399012
> 0 0
> AntiEntropyStage 0 0 0
> 0 0
> MigrationStage 0 0 30
> 0 0
> MemtablePostFlusher 0 0 279 0
> 0
> StreamStage 0 0 0
> 0 0
> FlushWriter 0 0 1846
> 0 1052
> MiscStage 0 0 0
> 0 0
> InternalResponseStage 0 0 0
> 0 0
> HintedHandoff 0 0 5
> 0 0
>
> Message type Dropped
> RANGE_SLICE 0
> READ_REPAIR 0
> BINARY 0
> READ 1
> MUTATION 1390
> REQUEST_RESPONSE 0
>
>
> # /opt/cassandra/bin/nodetool -h 127.0.0.1 -p 6080 info
> Token : 56713727820156410577229101238628035242
> Gossip active : true
> Load : 37.57 GB
> Generation No : 1339813956
> Uptime (seconds) : 120556
> Heap Memory (MB) : 3261.14 / 5984.00
> Data Center : datacenter1
> Rack : rack1
> Exceptions : 0
>
>
> INFO [ScheduledTasks:1] 2012-06-17 19:47:36,633 GCInspector.java (line
> 123) GC for ParNew: 222 ms for 1 collections, 2046077640 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:41,714 GCInspector.java (line
> 123) GC for ParNew: 262 ms for 1 collections, 2228128408 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:49,717 GCInspector.java (line
> 123) GC for ParNew: 237 ms for 1 collections, 2390412728 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:48:57,719 GCInspector.java (line
> 123) GC for ParNew: 223 ms for 1 collections, 2508702896 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:01,988 GCInspector.java (line
> 123) GC for ParNew: 232 ms for 1 collections, 2864574832 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:10,075 GCInspector.java (line
> 123) GC for ParNew: 208 ms for 1 collections, 2964629856 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:50:21,078 GCInspector.java (line
> 123) GC for ParNew: 258 ms for 1 collections, 3149127368 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:51:26,095 GCInspector.java (line
> 123) GC for ParNew: 213 ms for 1 collections, 3421495400 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:51:34,097 GCInspector.java (line
> 123) GC for ParNew: 218 ms for 1 collections, 3543978312 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,229 GCInspector.java (line
> 123) GC for ParNew: 221 ms for 1 collections, 3752290000 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:37,230 GCInspector.java (line
> 123) GC for ConcurrentMarkSweep: 206 ms for 1 collections, 3752313400 used;
> max is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:46,507 GCInspector.java (line
> 123) GC for ParNew: 243 ms for 1 collections, 3663162192 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:52:54,510 GCInspector.java (line
> 123) GC for ParNew: 283 ms for 1 collections, 1582282248 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:54:01,704 GCInspector.java (line
> 123) GC for ParNew: 235 ms for 1 collections, 1935534800 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:13,747 GCInspector.java (line
> 123) GC for ParNew: 233 ms for 1 collections, 2356975504 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:21,749 GCInspector.java (line
> 123) GC for ParNew: 264 ms for 1 collections, 2530976328 used; max
> is 6274678784
> INFO [ScheduledTasks:1] 2012-06-17 19:55:29,794 GCInspector.java (line
> 123) GC for ParNew: 224 ms for 1 collections, 2592311336 used; max
> is 6274678784
>
>
> BRs
> //Ares
>