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