cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Lee Mighdoll <...@underneath.ca>
Subject Re: delay/stall processing reads
Date Fri, 03 Jan 2014 05:34:23 GMT
>
> Well from what I see in system.log it does not appear that GC aligns with
> this delay.
>
Though it does seem like quite a few GCs take place. Here is my system.log
> around the time of the delay:
>

It does sound like a lot of CMS runs - you'd like most of your garbage to
be collected in new space (ParallelNew) not in old space (CMS).  It also
looks like your heap is staying fairly full - either CMS isn't recovering
much (most likely) or you're generating a lot of garbage.  I'm not familiar
with the GCInspector logs, though, so I may be guessing too far.

You can get gold standard gc logs by passing these parameters to the java
command when you launch cassandra:

-Xloggc:/path/to/where/to/put/the/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintPromotionFailure

Once you have good logs, more people (and tools) can help interpret them.

Cheers,
Lee


>
>  INFO [ScheduledTasks:1] 2014-01-02 12:30:22,164 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 479 ms for 1 collections, 7417499584 used;
> max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:30:37,579 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 557 ms for 1 collections, 7663015624 used;
> max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:31:50,416 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 633 ms for 1 collections, 6053238384used; max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:32:06,525 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 219 ms for 1 collections, 6430575008 used;
> max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:32:22,548 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 296 ms for 1 collections, 6732761584 used;
> max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:32:37,870 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 343 ms for 1 collections, 7020263776 used;
> max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:32:53,116 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 443 ms for 1 collections, 7276089816used; max is 8375238656
>  INFO [ScheduledTasks:1] 2014-01-02 12:33:08,557 GCInspector.java (line
> 116) GC for ConcurrentMarkSweep: 554 ms for 1 collections, 7662839184 used;
> max is 8375238656
>
> The earliest start time on my three delayed requests is 12:32:00.083 and
> they all clear out at 12:32:00.517. GC log events occur at 12:31:50 and at
> 21:32:06. The above entries are the only log entries in system.log at this
> time. Any other ideas?
>
> Is this type of GC frequency and delay "normal" ?
>
> thanks,
> Thunder
>
>
>
>
> On Thu, Jan 2, 2014 at 2:27 PM, Robert Coli <rcoli@eventbrite.com> wrote:
>
>> On Thu, Jan 2, 2014 at 2:24 PM, Thunder Stumpges <
>> thunder.stumpges@gmail.com> wrote:
>>
>>> Excuse my ignorance, but where would I look for the GC info? What logs
>>> contain this? I will start looking for log files and more clues in them.
>>>
>>
>> system.log contains some basic info, you can enable extended gc info via
>> options to the JVM.
>>
>> =Rob
>>
>>
>
>

Mime
View raw message