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 Sun, 17 Jun 2012 12:36:41 GMT
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