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