cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From aaron morton <aa...@thelastpickle.com>
Subject Re: GCInspector works every 10 seconds!
Date Mon, 18 Jun 2012 04:30:45 GMT
>   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.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