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 B09B19BB3 for ; Thu, 23 Feb 2012 20:14:28 +0000 (UTC) Received: (qmail 29621 invoked by uid 500); 23 Feb 2012 20:14:26 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 29594 invoked by uid 500); 23 Feb 2012 20:14:26 -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 29586 invoked by uid 99); 23 Feb 2012 20:14:26 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 23 Feb 2012 20:14:26 +0000 X-ASF-Spam-Status: No, hits=-0.7 required=5.0 tests=FSL_RCVD_USER,RCVD_IN_DNSWL_LOW,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of jbellis@gmail.com designates 209.85.214.44 as permitted sender) Received: from [209.85.214.44] (HELO mail-bk0-f44.google.com) (209.85.214.44) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 23 Feb 2012 20:14:18 +0000 Received: by bkuw12 with SMTP id w12so1622364bku.31 for ; Thu, 23 Feb 2012 12:13:58 -0800 (PST) Received-SPF: pass (google.com: domain of jbellis@gmail.com designates 10.204.10.91 as permitted sender) client-ip=10.204.10.91; Authentication-Results: mr.google.com; spf=pass (google.com: domain of jbellis@gmail.com designates 10.204.10.91 as permitted sender) smtp.mail=jbellis@gmail.com; dkim=pass header.i=jbellis@gmail.com Received: from mr.google.com ([10.204.10.91]) by 10.204.10.91 with SMTP id o27mr1434306bko.17.1330028038722 (num_hops = 1); Thu, 23 Feb 2012 12:13:58 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:in-reply-to:references:from:date:message-id:subject:to :content-type:content-transfer-encoding; bh=ehX09C1tU5N1kIZruVlDP0KNNAM484TMsUaHSkzgU1E=; b=wvVxuA3rPuhjkIkank2KtQV3NNWyFabRnX0wlENWikTnHU9iK1q+7+uJwNtWGc7K/F xD6MsjPy8/ZezTb/LmSmoRiW7X8h351KtOXrqGmzpc1vXCPODabIN/931vQUWfZ3phi2 zARPDoe70pL03TDmyZwHLUJDEHN7LuC6eQiSw= Received: by 10.204.10.91 with SMTP id o27mr1189437bko.17.1330028038519; Thu, 23 Feb 2012 12:13:58 -0800 (PST) MIME-Version: 1.0 Received: by 10.204.180.84 with HTTP; Thu, 23 Feb 2012 12:13:38 -0800 (PST) In-Reply-To: References: From: Jonathan Ellis Date: Thu, 23 Feb 2012 14:13:38 -0600 Message-ID: Subject: Re: GC performance in 1.0.x To: user@cassandra.apache.org Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org 30ms pauses are on the low side of normal for a 800MB young gen under parnew. We're not going to be able to get rid of those, although it looks like you're seeing objects in the young gen die *very* quickly, so cutting that to say 200MB might give you shorter (and more frequent) pauses for the young gen. If you can mail me the entire log file I can look to see if there were any stop-the-world full collections, which is where you'd see the multi-second pauses that we really want to avoid. On Sat, Feb 18, 2012 at 12:17 PM, Edward Capriolo w= rote: > MAX_HEAP_SIZE=3D"9G" > HEAP_NEWSIZE=3D"800M" > > 2 socket quad core > 44GB RAM > Cassandra 1.0.7 > > [edward@cdbla120 cassandra]$ free -g > =A0 =A0 =A0 =A0 =A0 =A0 total =A0 =A0 =A0 used =A0 =A0 =A0 free =A0 =A0 s= hared =A0 =A0buffers =A0 =A0 cached > Mem: =A0 =A0 =A0 =A0 =A0 =A043 =A0 =A0 =A0 =A0 34 =A0 =A0 =A0 =A0 =A08 = =A0 =A0 =A0 =A0 =A00 =A0 =A0 =A0 =A0 =A00 =A0 =A0 =A0 =A0 25 > -/+ buffers/cache: =A0 =A0 =A0 =A0 =A08 =A0 =A0 =A0 =A0 34 > Swap: =A0 =A0 =A0 =A0 =A0 =A00 =A0 =A0 =A0 =A0 =A00 =A0 =A0 =A0 =A0 =A00 > > # GC logging options -- uncomment to enable > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCDetails" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCDateStamps" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintHeapAtGC" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintTenuringDistribution" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCApplicationStoppedTime" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintPromotionFailure" > JVM_OPTS=3D"$JVM_OPTS -XX:PrintFLSStatistics=3D1" > JVM_OPTS=3D"$JVM_OPTS -Xloggc:/var/log/cassandra/gc-`date +%s`.log" > JVM_OPTS=3D"$JVM_OPTS -verbose:gc" > JVM_OPTS=3D"$JVM_OPTS -XX:+PrintSafepointStatistics" > > Three major column families using compression on two out of three. I > never really watched the gc logs too much before since i was disk > bound, but in this case I have all the data in main memory so limiting > pauses would be big for me. > > I see a good number of these: > > Total time for which application threads were stopped: 0.0301370 seconds > Total time for which application threads were stopped: 0.0046390 seconds > > [edward@cdbla120 cassandra]$ tail -400 gc-1329578417.log > Total Free Space: 637346254 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 482066 > Av. =A0Block =A0Size: 1322 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10516.947: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A0 =A048752 bytes, =A0 =A0 =A048752 total > : 7689K->5164K(737280K), 0.0173210 secs] 3594487K->3597704K(9355264K)Afte= r GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 636661736 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481773 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0204840 secs] [Times: user=3D0.19 sys=3D0.00, real=3D0.02 secs] > Heap after GC invocations=3D3856 (full 4): > =A0par new generation =A0 total 737280K, used 5164K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 6% used [0x00000005e2e00000, > 0x00000005e330b030, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3592540K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0251700 seconds > Total time for which application threads were stopped: 0.0046210 seconds > {Heap before GC invocations=3D3856 (full 4): > =A0par new generation =A0 total 737280K, used 660839K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, 100% used [0x00000005bae00000, > 0x00000005e2e00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 6% used [0x00000005e2e00000, > 0x00000005e3359df0, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3592540K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:35.980-0500: 10518.844: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 636661736 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481773 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10518.846: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A07128016 bytes, =A0 =A07128016 total > : 660839K->7853K(737280K), 0.0176930 secs] 4253380K->3600423K(9355264K)Af= ter GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 636661235 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481772 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0210680 secs] [Times: user=3D0.18 sys=3D0.00, real=3D0.02 secs] > Heap after GC invocations=3D3857 (full 4): > =A0par new generation =A0 total 737280K, used 7853K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 9% used [0x00000005e7e00000, > 0x00000005e85ab660, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3592570K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0256030 seconds > {Heap before GC invocations=3D3857 (full 4): > =A0par new generation =A0 total 737280K, used 7876K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae05ac0, 0x00000005e2e00000) > =A0from space 81920K, =A0 9% used [0x00000005e7e00000, > 0x00000005e85ab660, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3592570K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:36.006-0500: 10518.870: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 636661235 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481772 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10518.871: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A0 =A0 4912 bytes, =A0 =A0 =A0 4912 total > : 7876K->2197K(737280K), 0.0168170 secs] 3600446K->3601858K(9355264K)Afte= r GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 635807044 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481304 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0199700 secs] [Times: user=3D0.19 sys=3D0.00, real=3D0.02 secs] > Heap after GC invocations=3D3858 (full 4): > =A0par new generation =A0 total 737280K, used 2197K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 2% used [0x00000005e2e00000, > 0x00000005e3025410, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3599661K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0261540 seconds > {Heap before GC invocations=3D3858 (full 4): > =A0par new generation =A0 total 737280K, used 657515K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A099% used [0x00000005bae00000, > 0x00000005e2df5b20, 0x00000005e2e00000) > =A0from space 81920K, =A0 2% used [0x00000005e2e00000, > 0x00000005e3025410, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3599661K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:39.918-0500: 10522.782: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 635807044 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481304 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10522.784: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 18138696 bytes, =A0 18138696 total > : 657515K->18303K(737280K), 0.0225670 secs] > 4257177K->3617966K(9355264K)After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 635807044 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481304 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0259020 secs] [Times: user=3D0.25 sys=3D0.00, real=3D0.03 secs] > Heap after GC invocations=3D3859 (full 4): > =A0par new generation =A0 total 737280K, used 18303K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A022% used [0x00000005e7e00000, > 0x00000005e8fdffa8, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3599662K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0310430 seconds > Total time for which application threads were stopped: 0.0044970 seconds > {Heap before GC invocations=3D3859 (full 4): > =A0par new generation =A0 total 737280K, used 673663K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, 100% used [0x00000005bae00000, > 0x00000005e2e00000, 0x00000005e2e00000) > =A0from space 81920K, =A022% used [0x00000005e7e00000, > 0x00000005e8fdffa8, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3599662K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:43.662-0500: 10526.526: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 635807044 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 481304 > Av. =A0Block =A0Size: 1321 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10526.528: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A06231016 bytes, =A0 =A06231016 total > : 673663K->9643K(737280K), 0.0313290 secs] 4273326K->3621439K(9355264K)Af= ter GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 634281586 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 480350 > Av. =A0Block =A0Size: 1320 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0347120 secs] [Times: user=3D0.31 sys=3D0.00, real=3D0.03 secs] > Heap after GC invocations=3D3860 (full 4): > =A0par new generation =A0 total 737280K, used 9643K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A011% used [0x00000005e2e00000, > 0x00000005e376ade8, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3611796K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0398640 seconds > {Heap before GC invocations=3D3860 (full 4): > =A0par new generation =A0 total 737280K, used 664966K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A099% used [0x00000005bae00000, > 0x00000005e2df6be8, 0x00000005e2e00000) > =A0from space 81920K, =A011% used [0x00000005e2e00000, > 0x00000005e376ade8, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3611796K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:46.806-0500: 10529.671: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 634281586 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 480350 > Av. =A0Block =A0Size: 1320 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10529.672: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A05578880 bytes, =A0 =A05578880 total > : 664966K->8084K(737280K), 0.0217310 secs] 4276762K->3624063K(9355264K)Af= ter GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 633726004 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 480114 > Av. =A0Block =A0Size: 1319 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0251170 secs] [Times: user=3D0.22 sys=3D0.00, real=3D0.03 secs] > Heap after GC invocations=3D3861 (full 4): > =A0par new generation =A0 total 737280K, used 8084K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 9% used [0x00000005e7e00000, > 0x00000005e85e52f8, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3615978K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0301370 seconds > Total time for which application threads were stopped: 0.0046390 seconds > {Heap before GC invocations=3D3861 (full 4): > =A0par new generation =A0 total 737280K, used 663583K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, 100% used [0x00000005bae00000, > 0x00000005e2e00000, 0x00000005e2e00000) > =A0from space 81920K, =A010% used [0x00000005e7e00000, > 0x00000005e8607de8, 0x00000005ece00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e2e00000, > 0x00000005e2e00000, 0x00000005e7e00000) > =A0concurrent mark-sweep generation total 8617984K, used 3615978K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:49.225-0500: 10532.089: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 633726004 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 480114 > Av. =A0Block =A0Size: 1319 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10532.099: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A04626680 bytes, =A0 =A04626680 total > : 663583K->7027K(737280K), 0.0214590 secs] 4279561K->3626859K(9355264K)Af= ter GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 633246817 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 479921 > Av. =A0Block =A0Size: 1319 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0248210 secs] [Times: user=3D0.21 sys=3D0.00, real=3D0.03 secs] > Heap after GC invocations=3D3862 (full 4): > =A0par new generation =A0 total 737280K, used 7027K [0x00000005bae00000, > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A0 0% used [0x00000005bae00000, > 0x00000005bae00000, 0x00000005e2e00000) > =A0from space 81920K, =A0 8% used [0x00000005e2e00000, > 0x00000005e34dcd88, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3619831K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > } > Total time for which application threads were stopped: 0.0374180 seconds > {Heap before GC invocations=3D3862 (full 4): > =A0par new generation =A0 total 737280K, used 662376K [0x00000005bae00000= , > 0x00000005ece00000, 0x00000005ece00000) > =A0eden space 655360K, =A099% used [0x00000005bae00000, > 0x00000005e2dfd2b8, 0x00000005e2e00000) > =A0from space 81920K, =A0 8% used [0x00000005e2e00000, > 0x00000005e34dcd88, 0x00000005e7e00000) > =A0to =A0 space 81920K, =A0 0% used [0x00000005e7e00000, > 0x00000005e7e00000, 0x00000005ece00000) > =A0concurrent mark-sweep generation total 8617984K, used 3619831K > [0x00000005ece00000, 0x00000007fae00000, 0x00000007fae00000) > =A0concurrent-mark-sweep perm gen total 35796K, used 21382K > [0x00000007fae00000, 0x00000007fd0f5000, 0x0000000800000000) > 2012-02-18T13:15:52.121-0500: 10534.985: [GC Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 633246817 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 479921 > Av. =A0Block =A0Size: 1319 > Tree =A0 =A0 =A0Height: 34 > Before GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > 10534.987: [ParNew > Desired survivor size 41943040 bytes, new threshold 1 (max 1) > - age =A0 1: =A0 =A08678968 bytes, =A0 =A08678968 total > : 662376K->9883K(737280K), 0.0205490 secs] 4282207K->3632214K(9355264K)Af= ter GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 632933226 > Max =A0 Chunk Size: 138752484 > Number of Blocks: 479784 > Av. =A0Block =A0Size: 1319 > Tree =A0 =A0 =A0Height: 34 > After GC: > Statistics for BinaryTreeDictionary: > ------------------------------------ > Total Free Space: 1829376 > Max =A0 Chunk Size: 1829376 > Number of Blocks: 1 > Av. =A0Block =A0Size: 1829376 > Tree =A0 =A0 =A0Height: 1 > , 0.0239560 secs] > > On Sat, Feb 4, 2012 at 6:25 AM, Jonathan Ellis wrote: >> We put a bunch of effort into reducing GC pauses in 1.0, which worked >> great on our synthetic benchmarks but I don't have much data on how >> well that's working in practice, on real-world workloads. >> >> If you're running a Cassandra app in production or testing, I'd >> appreciate it if you could send me [either personally or via the list] >> the results of enabling GC logging on one of your nodes by >> uncommenting these lines in cassandra-env.sh: >> >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCDetails" >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCDateStamps" >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintHeapAtGC" >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintTenuringDistribution" >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintGCApplicationStoppedTime" >> # JVM_OPTS=3D"$JVM_OPTS -XX:+PrintPromotionFailure" >> # JVM_OPTS=3D"$JVM_OPTS -XX:PrintFLSStatistics=3D1" >> # JVM_OPTS=3D"$JVM_OPTS -Xloggc:/var/log/cassandra/gc-`date +%s`.log" >> >> (If you're running on Windows, you'll need to add these options >> manually to cassandra.bat, and hardcode the log filename.) >> >> Besides the log file itself it would be useful to know JVM version, >> how many cores your machine has, any GC options you have changed from >> the default, and a high-level description of your workload (write >> heavy? read heavy? slice reads, or query columns by name? =A0row cache >> enabled, and if so, serializingcache with jna, or on-heap cache?) >> >> Thanks! >> >> P.S. It would be simplest if you can provide results for 1.0.7, which >> IMO you would be well-served by upgrading to anyway, but all results >> for 1.0.2+ are useful if you specify the version you are on. >> >> -- >> Jonathan Ellis >> Project Chair, Apache Cassandra >> co-founder of DataStax, the source for professional Cassandra support >> http://www.datastax.com --=20 Jonathan Ellis Project Chair, Apache Cassandra co-founder of DataStax, the source for professional Cassandra support http://www.datastax.com