incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jason Tang <ares.t...@gmail.com>
Subject Re: GCInspector works every 10 seconds!
Date Mon, 18 Jun 2012 07:07:30 GMT
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 <aaron@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 <ares.tang@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
>>
>
>
>

Mime
View raw message