> > 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 <rc...@eventbrite.com> wrote: > >> On Thu, Jan 2, 2014 at 2:24 PM, Thunder Stumpges < >> thunder.stump...@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 >> >> > >
