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.t...@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 >
