Re: GCInspector works every 10 seconds!
On Mon, Jun 18, 2012 at 12:07 AM, Jason Tang ares.t...@gmail.com wrote: 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. The Key Cache is usually a win if added like this. The Row cache is less likely to be. If I were you I would check your row cache hit rates to make sure you are actually getting win. :) =Rob -- =Robert Coli AIMGTALK - rc...@palominodb.com YAHOO - rcoli.palominob SKYPE - rcoli_palominodb
Re: GCInspector works every 10 seconds!
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: 7fff0137f63408920e049c22:true:4@1339865451865018 DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408a0eeab052a: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: 0138ad1035880137f3372f3e0e28e3b6: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: 0138ad1035880137f33a80cf6cb5d383: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: 0138ad1035880137f330cd70c86690cd: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: 7fff0137f63408920e049c22:true:4@1339865451865018 DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408a0eeab052a:true:4@1339865451866000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408b1319577c9:true:4@1339865451867003 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408c081e0b8a3:true:4@1339865451867004 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340deefb8a0627:true:4@1339865451920001 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340df9c21e9979:true:4@1339865451923002 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e095ead1498:true:4@1339865451928000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e1af16cf151:true:4@1339865451935000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting
GCInspector works every 10 seconds!
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 NameActive Pending Completed Blocked All time blocked ReadStage 0 045387558 0 0 RequestResponseStage 0 096568347 0 0 MutationStage0 060215102 0 0 ReadRepairStage0 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 FlushWriter0 0 1846 0 1052 MiscStage 0 0 0 0 0 InternalResponseStage 0 0 00 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, 375229 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
Re: GCInspector works every 10 seconds!
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: 0138ad1035880137f3372f3e0e28e3b6: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: 0138ad1035880137f33a80cf6cb5d383: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: 0138ad1035880137f330cd70c86690cd: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: 7fff0137f63408920e049c22:true:4@1339865451865018 DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408a0eeab052a:true:4@1339865451866000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408b1319577c9:true:4@1339865451867003 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408c081e0b8a3:true:4@1339865451867004 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340deefb8a0627:true:4@1339865451920001 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340df9c21e9979:true:4@1339865451923002 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e095ead1498:true:4@1339865451928000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e1af16cf151:true:4@1339865451935000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e396cfdc9fa:true:4@133986545195 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 NameActive Pending Completed Blocked All time blocked ReadStage 0 045387558 0 0 RequestResponseStage 0 096568347 0 0 MutationStage0 060215102 0 0 ReadRepairStage0 0 0 0 0 ReplicateOnWriteStage 0 0 0
Re: GCInspector works every 10 seconds!
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: 7fff0137f63408920e049c22:true:4@1339865451865018 DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408a0eeab052a: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: 0138ad1035880137f3372f3e0e28e3b6: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: 0138ad1035880137f33a80cf6cb5d383: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: 0138ad1035880137f330cd70c86690cd: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: 7fff0137f63408920e049c22:true:4@1339865451865018 DEBUG [ReadStage:89] 2012-06-17 20:17:26,958 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408a0eeab052a:true:4@1339865451866000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408b1319577c9:true:4@1339865451867003 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f63408c081e0b8a3:true:4@1339865451867004 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340deefb8a0627:true:4@1339865451920001 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340df9c21e9979:true:4@1339865451923002 DEBUG [ReadStage:89] 2012-06-17 20:17:26,959 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e095ead1498:true:4@1339865451928000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e1af16cf151:true:4@1339865451935000 DEBUG [ReadStage:89] 2012-06-17 20:17:26,960 SliceQueryFilter.java (line 123) collecting 0 of 5000: 7fff0137f6340e396cfdc9fa:true:4@133986545195 BRs //Ares 2012/6/17 Jason Tang ares.t...@gmail.com Hi After running load testing for 24 hours(insert, update
