Return-Path: X-Original-To: apmail-cassandra-user-archive@www.apache.org Delivered-To: apmail-cassandra-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id BD009100A4 for ; Wed, 19 Jun 2013 01:15:36 +0000 (UTC) Received: (qmail 9568 invoked by uid 500); 19 Jun 2013 01:15:34 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 9487 invoked by uid 500); 19 Jun 2013 01:15:34 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 9479 invoked by uid 99); 19 Jun 2013 01:15:34 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 19 Jun 2013 01:15:34 +0000 X-ASF-Spam-Status: No, hits=1.5 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of tsato@cloudian.com designates 209.85.160.41 as permitted sender) Received: from [209.85.160.41] (HELO mail-pb0-f41.google.com) (209.85.160.41) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 19 Jun 2013 01:15:28 +0000 Received: by mail-pb0-f41.google.com with SMTP id rp16so4486649pbb.0 for ; Tue, 18 Jun 2013 18:15:07 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=message-id:date:from:user-agent:mime-version:to:subject:references :in-reply-to:content-type:x-gm-message-state; bh=FqzWU/f1NT90rqjpX9gVhxwJQ/PZHqsFuJNAbiiVDv4=; b=ABZst9rfaacMWSi2KRVZDGyPklVXvy6xXFaSR6Q/JCKzNHyt9Ny58mjtJbwuXDGKXB Nr6XKS7aT28+/4u7d6+th6CGXncMdiEL1UfLY67GfJ5ITnMTbymqffT9vDLv0SPU9/kf DcMbhq9x51a+owAnFo9HT1ktYkrqcK7x6YV3zIXGzZdapqRt/H+NlN5CIRy3VzpFKbES nJY6ZWXE1kDIF017+V4+PlSZAGZbrWiWLsaaSSzpzbBscMNEBb7ieP9HDtRPOATEtmxJ hpiEvMD8docP5Jt1YBnIsJQBoxfgO526ySXmJm7h1ohMbB5o1i3Kb+2r2FQ+pEsiwciG sIjQ== X-Received: by 10.66.145.34 with SMTP id sr2mr4321121pab.94.1371604507364; Tue, 18 Jun 2013 18:15:07 -0700 (PDT) Received: from [10.181.164.183] (124x35x137x114.ap124.ftth.ucom.ne.jp. [124.35.137.114]) by mx.google.com with ESMTPSA id p2sm22017827pag.22.2013.06.18.18.15.05 for (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Tue, 18 Jun 2013 18:15:06 -0700 (PDT) Message-ID: <51C1061F.7020800@cloudian.com> Date: Wed, 19 Jun 2013 10:15:11 +0900 From: "Takenori Sato(Cloudian)" User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20130509 Thunderbird/17.0.6 MIME-Version: 1.0 To: user@cassandra.apache.org Subject: Re: Reduce Cassandra GC References: <51B237BA.9060809@4friends.od.ua> <6D3C4DCA-8CD6-4D3E-915D-66CFF8323F13@gmail.com> In-Reply-To: Content-Type: multipart/alternative; boundary="------------000602020607020503020801" X-Gm-Message-State: ALoCoQkcCmxHCgaLPdhPpDvCtn/3DJjqqiBJNaR9AP5zG+Ecnfb2VUoa1pM+64HjR+pfrluqVsCp X-Virus-Checked: Checked by ClamAV on apache.org This is a multi-part message in MIME format. --------------000602020607020503020801 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Oops, sorry. I missed that. As you see, if the ParNew GC have waited for such a CMS GC by promotion failure, it would make sense. But unfortunatelly, the time is different. By 2 mins. 2013-06-17T08:11:22.300+0000: 2551.288: [GC 870971K->216494K(4018176K), 145.1887460 secs] ... 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 Just to make sure, can you post your Cassandra's ps info? (2013/06/19 0:48), Joel Samuelsson 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 > > > 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 > > 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 > > > 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 > > 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 > > > > 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. > > > > > > --------------000602020607020503020801 Content-Type: text/html; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Oops, sorry. I missed that.

As you see, if the ParNew GC have waited for such a CMS GC by promotion failure, it would make sense. But unfortunatelly, the time is different.  By 2 mins.

2013-06-17T08:11:22.300+0000: 2551.288: [GC 870971K->216494K(4018176K), 145.1887460 secs]
...
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

Just to make sure, can you post your Cassandra's ps info?

(2013/06/19 0:48), Joel Samuelsson 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 <tsato@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.joel@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 <tsato@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.joel@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.joel@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.






--------------000602020607020503020801--