Yes, like I said, the only relevant output from that file was: 2013-06-17T08:11:22.300+0000: 2551.288: [GC 870971K->216494K(4018176K), 145.1887460 secs]
2013/6/18 Takenori Sato <ts...@cloudian.com> > GC logging is not in system.log. But in the following file. > > JVM_OPTS="$JVM_OPTS -Xloggc:/var/log/cassandra/gc-`date +%s`.log" > > > At least, no GC logs are shown in your post. > > > On Tue, Jun 18, 2013 at 5:05 PM, Joel Samuelsson < > samuelsson.j...@gmail.com> wrote: > >> Can't find any promotion failure. >> >> In system.log this is what I get: >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,490 GCInspector.java (line >> 122) GC for ParNew: 145189 ms for 1 collections, 225905072 used; max is >> 4114612224 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,490 StatusLogger.java (line >> 57) Pool Name Active Pending Blocked >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,491 StatusLogger.java (line >> 72) ReadStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,492 StatusLogger.java (line >> 72) RequestResponseStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,492 StatusLogger.java (line >> 72) ReadRepairStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,492 StatusLogger.java (line >> 72) MutationStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,493 StatusLogger.java (line >> 72) ReplicateOnWriteStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,493 StatusLogger.java (line >> 72) GossipStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,493 StatusLogger.java (line >> 72) AntiEntropyStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,494 StatusLogger.java (line >> 72) MigrationStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,494 StatusLogger.java (line >> 72) StreamStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,494 StatusLogger.java (line >> 72) MemtablePostFlusher 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,495 StatusLogger.java (line >> 72) FlushWriter 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,495 StatusLogger.java (line >> 72) MiscStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,499 StatusLogger.java (line >> 72) commitlog_archiver 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,499 StatusLogger.java (line >> 72) InternalResponseStage 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,499 StatusLogger.java (line >> 72) HintedHandoff 0 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,500 StatusLogger.java (line >> 77) CompactionManager 0 0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,500 StatusLogger.java (line >> 89) MessagingService n/a 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,500 StatusLogger.java (line >> 99) Cache Type Size Capacity KeysToSave Provider >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,504 StatusLogger.java (line >> 100) KeyCache 12129 2184533 all >> >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,505 StatusLogger.java (line >> 106) RowCache 0 0 all >> org.apache.cassandra.cache.SerializingCacheProvider >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,505 StatusLogger.java (line >> 113) ColumnFamily Memtable ops,data >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,505 StatusLogger.java (line >> 116) system.NodeIdInfo 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,505 StatusLogger.java (line >> 116) system.IndexInfo 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,505 StatusLogger.java (line >> 116) system.LocationInfo 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,506 StatusLogger.java (line >> 116) system.Versions 3,103 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,506 StatusLogger.java (line >> 116) system.schema_keyspacees 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,506 StatusLogger.java (line >> 116) system.Migrations 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,506 StatusLogger.java (line >> 116) system.schema_columnfamilies 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,506 StatusLogger.java (line >> 116) system.schema_columns 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,507 StatusLogger.java (line >> 116) system.HintsColumnFamily 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,507 StatusLogger.java (line >> 116) system.Schema 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,507 StatusLogger.java (line >> 116) Keyspace.cf01 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,507 StatusLogger.java (line >> 116) Keyspace.cf02 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,507 StatusLogger.java (line >> 116) Keyspace.cf03 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf04 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf05 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf06 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf07 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf08 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,508 StatusLogger.java (line >> 116) Keyspace.cf09 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,509 StatusLogger.java (line >> 116) Keyspace.cf10 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,509 StatusLogger.java (line >> 116) Keyspace.cf11 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,509 StatusLogger.java (line >> 116) Keyspace.cf12 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,509 StatusLogger.java (line >> 116) Keyspace.cf13 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,509 StatusLogger.java (line >> 116) Keyspace.cf14 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,510 StatusLogger.java (line >> 116) Keyspace.cf15 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,510 StatusLogger.java (line >> 116) Keyspace.cf16 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,510 StatusLogger.java (line >> 116) Keyspace.cf17 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,510 StatusLogger.java (line >> 116) Keyspace.cf18 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,510 StatusLogger.java (line >> 116) Keyspace.cf19 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,511 StatusLogger.java (line >> 116) Keyspace.cf20 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,511 StatusLogger.java (line >> 116) Keyspace.cf21 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,511 StatusLogger.java (line >> 116) Keyspace.cf22 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,511 StatusLogger.java (line >> 116) Keyspace.cf23 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,511 StatusLogger.java (line >> 116) Keyspace.cf24 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,512 StatusLogger.java (line >> 116) Keyspace.cf25 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,512 StatusLogger.java (line >> 116) Keyspace.cf26 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,512 StatusLogger.java (line >> 116) StressKeyspace.StressStandard 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,512 StatusLogger.java (line >> 116) testing_Keyspace.cf01 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,512 StatusLogger.java (line >> 116) testing_Keyspace.cf02 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,513 StatusLogger.java (line >> 116) testing_Keyspace.cf03 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,513 StatusLogger.java (line >> 116) testing_Keyspace.cf04 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,513 StatusLogger.java (line >> 116) testing_Keyspace.cf05 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,513 StatusLogger.java (line >> 116) testing_Keyspace.cf06 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,513 StatusLogger.java (line >> 116) testing_Keyspace.cf07 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,514 StatusLogger.java (line >> 116) testing_Keyspace.cf08 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,514 StatusLogger.java (line >> 116) testing_Keyspace.cf09 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,514 StatusLogger.java (line >> 116) testing_Keyspace.cf10 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,514 StatusLogger.java (line >> 116) testing_Keyspace.cf11 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,514 StatusLogger.java (line >> 116) testing_Keyspace.cf12 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,515 StatusLogger.java (line >> 116) testing_Keyspace.cf13 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,515 StatusLogger.java (line >> 116) testing_Keyspace.cf14 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,515 StatusLogger.java (line >> 116) testing_Keyspace.cf15 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,515 StatusLogger.java (line >> 116) testing_Keyspace.cf16 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,515 StatusLogger.java (line >> 116) testing_Keyspace.cf17 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,516 StatusLogger.java (line >> 116) testing_Keyspace.cf18 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,516 StatusLogger.java (line >> 116) testing_Keyspace.cf19 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,516 StatusLogger.java (line >> 116) testing_Keyspace.cf20 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,516 StatusLogger.java (line >> 116) testing_Keyspace.cf21 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,517 StatusLogger.java (line >> 116) testing_Keyspace.cf22 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,517 StatusLogger.java (line >> 116) OpsCenter.rollups7200 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,517 StatusLogger.java (line >> 116) OpsCenter.rollups86400 0,0 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,517 StatusLogger.java (line >> 116) OpsCenter.rollups60 13745,3109686 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,517 StatusLogger.java (line >> 116) OpsCenter.events 18,826 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,518 StatusLogger.java (line >> 116) OpsCenter.rollups300 2516,570931 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,519 StatusLogger.java (line >> 116) OpsCenter.pdps 9072,160850 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,519 StatusLogger.java (line >> 116) OpsCenter.events_timeline 3,86 >> INFO [ScheduledTasks:1] 2013-06-17 08:13:47,520 StatusLogger.java (line >> 116) OpsCenter.settings 0,0 >> >> And from gc-1371454124.log I get: >> 2013-06-17T08:11:22.300+0000: 2551.288: [GC 870971K->216494K(4018176K), >> 145.1887460 secs] >> >> >> 2013/6/18 Takenori Sato <ts...@cloudian.com> >> >>> Find "promotion failure". Bingo if it happened at the time. >>> >>> Otherwise, post the relevant portion of the log here. Someone may find a >>> hint. >>> >>> >>> On Mon, Jun 17, 2013 at 5:51 PM, Joel Samuelsson < >>> samuelsson.j...@gmail.com> wrote: >>> >>>> Just got a very long GC again. What am I to look for in the logging I >>>> just enabled? >>>> >>>> >>>> 2013/6/17 Joel Samuelsson <samuelsson.j...@gmail.com> >>>> >>>>> > If you are talking about 1.2.x then I also have memory problems on >>>>> the idle cluster: java memory constantly slow grows up to limit, then >>>>> spend >>>>> long time for GC. I never seen such behaviour for 1.0.x and 1.1.x, where >>>>> on idle cluster java memory stay on the same value. >>>>> >>>>> No I am running Cassandra 1.1.8. >>>>> >>>>> > Can you paste you gc config? >>>>> >>>>> I believe the relevant configs are these: >>>>> # GC tuning options >>>>> JVM_OPTS="$JVM_OPTS -XX:+UseParNewGC" >>>>> JVM_OPTS="$JVM_OPTS -XX:+UseConcMarkSweepGC" >>>>> JVM_OPTS="$JVM_OPTS -XX:+CMSParallelRemarkEnabled" >>>>> JVM_OPTS="$JVM_OPTS -XX:SurvivorRatio=8" >>>>> JVM_OPTS="$JVM_OPTS -XX:MaxTenuringThreshold=1" >>>>> JVM_OPTS="$JVM_OPTS -XX:CMSInitiatingOccupancyFraction=75" >>>>> JVM_OPTS="$JVM_OPTS -XX:+UseCMSInitiatingOccupancyOnly" >>>>> >>>>> I haven't changed anything in the environment config up until now. >>>>> >>>>> > Also can you take a heap dump at 2 diff points so that we can >>>>> compare it? >>>>> >>>>> I can't access the machine at all during the stop-the-world freezes. >>>>> Was that what you wanted me to try? >>>>> >>>>> > Uncomment the followings in "cassandra-env.sh". >>>>> Done. Will post results as soon as I get a new stop-the-world gc. >>>>> >>>>> > If you are unable to find a JIRA, file one >>>>> >>>>> Unless this turns out to be a problem on my end, I will. >>>>> >>>> >>>> >>> >> >
