Is your young generation size set to 4GB? Can you paste the output of ps -ef|grep cassandra ? On Tue, Jun 18, 2013 at 8:48 AM, Joel Samuelsson <samuelsson.j...@gmail.com>wrote:
> 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. >>>>>> >>>>> >>>>> >>>> >>> >> >
