Thanks Lee, I put these in place on one of the three servers, and while doing so I noticed in the logs on the other servers that there were many errors from our weekly nodetool repair of this form:
On Thu, Jan 2, 2014 at 9:34 PM, Lee Mighdoll <l...@underneath.ca> wrote: > 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 >>> >>> >> >> >
