Strange Long ParNew GC Pauses (Sample Code Included)
Mikael Gerdin
mikael.gerdin at oracle.com
Mon May 4 12:55:25 UTC 2015
Just fyi, this issue is now https://bugs.openjdk.java.net/browse/JDK-8079274
/Mikael
On 2015-04-30 19:50, James Lent wrote:
> I will give it a read.
>
> In the mean time I tested with Oracle Java 6 and it seems OK with the
> BlockOffsetArrayUseUnallocatedBlock either enabled or disabled.
>
> To me that indicates something happened in Java 7 and filtered back to
> Open JDK 6 (my understanding is that the OpenJDK 6 genealogy is a bit
> complicated).
>
> I don't think the times in the second example below can be justified by
> "legitimately" dirty cards. Approximately the same number of new
> objects are allocated between each ParNew cycle and yet the ParNewGC
> times in that example grow steadily after the first few cycles. It
> start at about 0.03 seconds and then starts increasing by about 5
> seconds each cycle. When I finally kill the process it is taking 58.93
> seconds (keeping 4 CPUs busy for 232.31 seconds). The fact that is
> comes back at all is the most amazing part to me.
>
> Further, the (one and only) ArrayList should not get promoted to Old
> memory until many cycles have gone by and it is the only object in
> Tenured memory that should have any references back to the objects I am
> creating in New memory (i.e.,. there should not be that many dirty cards
> created by the application code each cycle until that ArrayList gets
> very big and perhaps moved).
>
> In the first case below the system seems to recover after just a few
> expensive cycles. Very different behavior.
>
> Finally the sensitivity of the problem to the size of the static object
> (the 32M "bad" range) makes me very suspicious. The static object
> starts its life Tenured memory and should have no references to any
> objects in New memory (it contains no references at all).
>
> Of course the "card table" concept is new to me so I could be missing
> something.
>
>> You could try
>> http://blog.ragozin.info/2012/03/secret-hotspot-option-improving-gc.html which
>> talks about an option that is safe but still diagnostic, though it
>> doesn’t seem like your heap is that big
>>
>> Assuming the large object (in this case your arraylist(s) since they
>> are going to be growing) is an array of object pointers, then the
>> sensitivity to size is likely due to whether it gets promoted to or
>> allocated immediately in the old gen, but mostly populated with new
>> gen objects. If so the next young gen GC is likely to be slow, since
>> most cards will be dirty.
>>
>>> On Apr 30, 2015, at 11:21 AM, James Lent <jlent at tivo.com
>>> <mailto:jlent at tivo.com>> wrote:
>>>
>>> Thanks the quick response and taking the time to reproduce the issue. A
>>> card table problem (corruption?) makes sense to me (although I had never
>>> heard the term "card table" until a couple of days ago when I was doing
>>> some random GC research, so what do I know).
>>>
>>> Let me see if I understand the Bugs you referenced:
>>>
>>> JDK-8079128 - Seems to reference a 100% increase in ParNewGC times.
>>> That seems pretty tame compared to this issue. In this case the
>>> behavior looks insane. A 100% increase would be about 0.02 seconds.
>>>
>>> JDK-7040068 - Seems to report that the
>>> BlockOffsetArrayUseUnallocatedBlock is dangerous.
>>>
>>> I did check and it is enabled in my Oracle Java 6 JVM by default, but,
>>> is not even displayed as an option in my OpenJDK 6-8 and Oracle 7-8 JVMs:
>>>
>>> /usr/lib/jvm/java-6-oracle/bin/java -XX:+PrintFlagsFinal -version |
>>> grep BlockOffsetArrayUseUnallocatedBlock
>>> bool BlockOffsetArrayUseUnallocatedBlock = true
>>> {product}
>>> java version "1.6.0_45"
>>> Java(TM) SE Runtime Environment (build 1.6.0_45-b06)
>>> Java HotSpot(TM) 64-Bit Server VM (build 20.45-b01, mixed mode)
>>>
>>> /usr/lib/jvm/java-8-oracle/bin/java -XX:+PrintFlagsFinal -version |
>>> grep BlockOffsetArrayUseUnallocatedBlock
>>> java version "1.8.0_45"
>>> Java(TM) SE Runtime Environment (build 1.8.0_45-b14)
>>> Java HotSpot(TM) 64-Bit Server VM (build 25.45-b02, mixed mode)
>>>
>>> I tried to enable it in Oracle 8 and got the following message:
>>>
>>> /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc -XX:+PrintGCTimeStamps
>>> -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx6G
>>> -Xms6G -XX:+BlockOffsetArrayUseUnallocatedBlock LongParNewPause
>>> $((500*1024*1024)) 100 100
>>> Error: VM option 'BlockOffsetArrayUseUnallocatedBlock' is diagnostic and
>>> must be enabled via -XX:+UnlockDiagnosticVMOptions.
>>> Error: Could not create the Java Virtual Machine.
>>> Error: A fatal exception has occurred. Program will exit.
>>>
>>> That is consistent with your statement that it is not recommended - our
>>> operations folks are unlikely to go for that.
>>>
>>> This bug makes me think that not enabling it also has serious issues.
>>>
>>>> Hi James,
>>>>
>>>> I did a quick perf inspection and saw a lot of time spent scanning the
>>>> card table, so on a hunch I ran your sample program with
>>>> -XX:+BlockOffsetArrayUseUnallocatedBlock
>>>> and that appears to make the extreme pause times go away.
>>>>
>>>> See https://bugs.openjdk.java.net/browse/JDK-8079128
>>>> and https://bugs.openjdk.java.net/browse/JDK-7040068
>>>>
>>>> I don't have time to dig further into this just at this moment, and
>>>> running with that flag can cause random crashes and is not recommended.
>>>>
>>>> /Mikael
>>>>
>>>> On 2015-04-30 17:01, James Lent wrote:
>>>>> Here is a more frightening example:
>>>>>
>>>>> Bad Case - 500M Static Object:
>>>>>
>>>>> java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
>>>>> -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx6G -Xms6G LongParNewPause
>>>>> $((500*1024*1024)) 100 100
>>>>> 0.309: [GC0.309: [ParNew: 272640K->3028K(306688K), 0.0287780 secs]
>>>>> 784640K->515028K(6257408K), 0.0288700 secs] [Times: user=0.08 sys=0.01,
>>>>> real=0.03 secs]
>>>>> 0.372: [GC0.372: [ParNew: 275668K->7062K(306688K), 0.0228070 secs]
>>>>> 787668K->519062K(6257408K), 0.0228580 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 0.430: [GC0.430: [ParNew: 279702K->11314K(306688K), 0.0327930 secs]
>>>>> 791702K->523314K(6257408K), 0.0328510 secs] [Times: user=0.08 sys=0.01,
>>>>> real=0.03 secs]
>>>>> 0.497: [GC0.497: [ParNew: 283954K->15383K(306688K), 0.0336020 secs]
>>>>> 795954K->527383K(6257408K), 0.0336550 secs] [Times: user=0.08 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 0.565: [GC0.565: [ParNew: 288023K->21006K(306688K), 0.0282110 secs]
>>>>> 800023K->533006K(6257408K), 0.0282740 secs] [Times: user=0.08 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 0.627: [GC0.627: [ParNew: 293646K->26805K(306688K), 0.0265270 secs]
>>>>> 805646K->538805K(6257408K), 0.0266220 secs] [Times: user=0.07 sys=0.01,
>>>>> real=0.03 secs]
>>>>> 0.688: [GC0.688: [ParNew: 299445K->20215K(306688K), 1.3657150 secs]
>>>>> 811445K->535105K(6257408K), 1.3657830 secs] [Times: user=3.97 sys=0.01,
>>>>> real=1.36 secs]
>>>>> 2.087: [GC2.087: [ParNew: 292855K->17914K(306688K), 6.6188870 secs]
>>>>> 807745K->535501K(6257408K), 6.6189490 secs] [Times: user=19.71
>>>>> sys=0.03,
>>>>> real=6.61 secs]
>>>>> 8.741: [GC8.741: [ParNew: 290554K->17433K(306688K), 14.2495190 secs]
>>>>> 808141K->537744K(6257408K), 14.2495830 secs] [Times: user=42.34
>>>>> sys=0.10, real=14.25 secs]
>>>>> 23.025: [GC23.025: [ParNew: 290073K->17315K(306688K), 21.1579920 secs]
>>>>> 810384K->540348K(6257408K), 21.1580510 secs] [Times: user=70.10
>>>>> sys=0.08, real=21.16 secs]
>>>>> 44.216: [GC44.216: [ParNew: 289955K->17758K(306688K), 27.6932380 secs]
>>>>> 812988K->543511K(6257408K), 27.6933060 secs] [Times: user=103.91
>>>>> sys=0.16, real=27.69 secs]
>>>>> 71.941: [GC71.941: [ParNew: 290398K->17745K(306688K), 35.1077720 secs]
>>>>> 816151K->546225K(6257408K), 35.1078600 secs] [Times: user=130.86
>>>>> sys=0.10, real=35.11 secs]
>>>>> 107.081: [GC107.081: [ParNew: 290385K->21826K(306688K), 41.4425020
>>>>> secs]
>>>>> 818865K->553022K(6257408K), 41.4425720 secs] [Times: user=158.25
>>>>> sys=0.31, real=41.44 secs]
>>>>> 148.555: [GC148.555: [ParNew: 294466K->21834K(306688K), 45.9826660
>>>>> secs]
>>>>> 825662K->555757K(6257408K), 45.9827260 secs] [Times: user=180.91
>>>>> sys=0.14, real=45.98 secs]
>>>>> 194.570: [GC194.570: [ParNew: 294474K->21836K(306688K), 51.5779770
>>>>> secs]
>>>>> 828397K->558485K(6257408K), 51.5780450 secs] [Times: user=204.05
>>>>> sys=0.20, real=51.58 secs]
>>>>> 246.180: [GC246.180: [ParNew^C: 294476K->18454K(306688K), 58.9307800
>>>>> secs] 831125K->557829K(6257408K), 58.9308660 secs] [Times: user=232.31
>>>>> sys=0.23, real=58.93 secs]
>>>>> Heap
>>>>> par new generation total 306688K, used 40308K [0x000000067ae00000,
>>>>> 0x000000068fac0000, 0x000000068fac0000)
>>>>> eden space 272640K, 8% used [0x000000067ae00000,
>>>>> 0x000000067c357980, 0x000000068b840000)
>>>>> from space 34048K, 54% used [0x000000068b840000, 0x000000068ca458f8,
>>>>> 0x000000068d980000)
>>>>> to space 34048K, 0% used [0x000000068d980000, 0x000000068d980000,
>>>>> 0x000000068fac0000)
>>>>> concurrent mark-sweep generation total 5950720K, used 539375K
>>>>> [0x000000068fac0000, 0x00000007fae00000, 0x00000007fae00000)
>>>>> concurrent-mark-sweep perm gen total 21248K, used 2435K
>>>>> [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
>>>>>
>>>>> Good Case - 479M Static Object:
>>>>>
>>>>> java -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
>>>>> -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx6G -Xms6G LongParNewPause
>>>>> $((479*1024*1024)) 100 100
>>>>> 0.298: [GC0.298: [ParNew: 272640K->3036K(306688K), 0.0152390 secs]
>>>>> 763136K->493532K(6257408K), 0.0153450 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.346: [GC0.346: [ParNew: 275676K->7769K(306688K), 0.0193840 secs]
>>>>> 766172K->498265K(6257408K), 0.0194570 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.398: [GC0.398: [ParNew: 280409K->11314K(306688K), 0.0203460 secs]
>>>>> 770905K->501810K(6257408K), 0.0204080 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.450: [GC0.450: [ParNew: 283954K->17306K(306688K), 0.0222390 secs]
>>>>> 774450K->507802K(6257408K), 0.0223070 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.504: [GC0.504: [ParNew: 289946K->18380K(306688K), 0.0169000 secs]
>>>>> 780442K->508876K(6257408K), 0.0169630 secs] [Times: user=0.07 sys=0.01,
>>>>> real=0.02 secs]
>>>>> 0.552: [GC0.552: [ParNew: 291020K->26805K(306688K), 0.0203990 secs]
>>>>> 781516K->517301K(6257408K), 0.0204620 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.604: [GC0.604: [ParNew: 299445K->21153K(306688K), 0.0230980 secs]
>>>>> 789941K->514539K(6257408K), 0.0231610 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.659: [GC0.659: [ParNew: 293793K->29415K(306688K), 0.0170240 secs]
>>>>> 787179K->525498K(6257408K), 0.0170970 secs] [Times: user=0.07 sys=0.01,
>>>>> real=0.02 secs]
>>>>> 0.708: [GC0.708: [ParNew: 302055K->23874K(306688K), 0.0202970 secs]
>>>>> 798138K->522681K(6257408K), 0.0203600 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.759: [GC0.760: [ParNew: 296514K->26842K(306688K), 0.0238600 secs]
>>>>> 795321K->528371K(6257408K), 0.0239390 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 0.815: [GC0.815: [ParNew: 299482K->25343K(306688K), 0.0237580 secs]
>>>>> 801011K->529592K(6257408K), 0.0238030 secs] [Times: user=0.06 sys=0.01,
>>>>> real=0.02 secs]
>>>>> 0.870: [GC0.870: [ParNew: 297983K->25767K(306688K), 0.0195800 secs]
>>>>> 802232K->532743K(6257408K), 0.0196290 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.921: [GC0.921: [ParNew: 298407K->21795K(306688K), 0.0196310 secs]
>>>>> 805383K->531488K(6257408K), 0.0196960 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 0.972: [GC0.972: [ParNew: 294435K->25910K(306688K), 0.0242780 secs]
>>>>> 804128K->538329K(6257408K), 0.0243440 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.028: [GC1.028: [ParNew: 298550K->21834K(306688K), 0.0235000 secs]
>>>>> 810969K->536979K(6257408K), 0.0235600 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.083: [GC1.083: [ParNew: 294474K->26625K(306688K), 0.0188330 secs]
>>>>> 809619K->544497K(6257408K), 0.0188950 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.133: [GC1.133: [ParNew: 299265K->26602K(306688K), 0.0210780 secs]
>>>>> 817137K->547186K(6257408K), 0.0211380 secs] [Times: user=0.06 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.185: [GC1.185: [ParNew: 299242K->26612K(306688K), 0.0236720 secs]
>>>>> 819826K->549922K(6257408K), 0.0237230 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.240: [GC1.241: [ParNew: 299252K->26615K(306688K), 0.0188560 secs]
>>>>> 822562K->552651K(6257408K), 0.0189150 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.291: [GC1.291: [ParNew: 299255K->26615K(306688K), 0.0195090 secs]
>>>>> 825291K->555378K(6257408K), 0.0195870 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.342: [GC1.342: [ParNew: 299255K->22531K(306688K), 0.0229010 secs]
>>>>> 828018K->554021K(6257408K), 0.0229610 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.396: [GC1.396: [ParNew: 295171K->24505K(306688K), 0.0265920 secs]
>>>>> 826661K->560810K(6257408K), 0.0266360 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.453: [GC1.453: [ParNew: 297145K->24529K(306688K), 0.0296490 secs]
>>>>> 833450K->563560K(6257408K), 0.0297070 secs] [Times: user=0.09 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.514: [GC1.514: [ParNew: 297169K->27700K(306688K), 0.0259820 secs]
>>>>> 836200K->569458K(6257408K), 0.0260310 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.571: [GC1.572: [ParNew: 300340K->27666K(306688K), 0.0199210 secs]
>>>>> 842098K->572150K(6257408K), 0.0199650 secs] [Times: user=0.07 sys=0.01,
>>>>> real=0.02 secs]
>>>>> 1.623: [GC1.623: [ParNew: 300306K->27658K(306688K), 0.0237020 secs]
>>>>> 844790K->574868K(6257408K), 0.0237630 secs] [Times: user=0.08 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.678: [GC1.678: [ParNew: 300298K->31737K(306688K), 0.0237820 secs]
>>>>> 847508K->581674K(6257408K), 0.0238530 secs] [Times: user=0.08 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.733: [GC1.733: [ParNew: 304377K->21022K(306688K), 0.0265400 secs]
>>>>> 854314K->573685K(6257408K), 0.0265980 secs] [Times: user=0.08 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.791: [GC1.791: [ParNew: 293662K->25359K(306688K), 0.0249520 secs]
>>>>> 846325K->580748K(6257408K), 0.0250050 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.847: [GC1.847: [ParNew: 297999K->19930K(306688K), 0.0195120 secs]
>>>>> 853388K->581179K(6257408K), 0.0195650 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 1.898: [GC1.898: [ParNew: 292570K->20318K(306688K), 0.0233960 secs]
>>>>> 853819K->584294K(6257408K), 0.0234650 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 1.953: [GC1.953: [ParNew: 292958K->20415K(306688K), 0.0233530 secs]
>>>>> 856934K->587117K(6257408K), 0.0234130 secs] [Times: user=0.07 sys=0.00,
>>>>> real=0.02 secs]
>>>>> 2.007: [GC2.007: [ParNew: 293055K->20439K(306688K), 0.0301410 secs]
>>>>> 859757K->589868K(6257408K), 0.0302070 secs] [Times: user=0.09 sys=0.00,
>>>>> real=0.03 secs]
>>>>> 2.068: [GC2.068: [ParNew: 293079K->20445K(306688K), 0.0289190 secs]
>>>>> 862508K->592600K(6257408K), 0.0289690 secs] [Times: user=0.09 sys=0.00,
>>>>> real=0.03 secs]
>>>>> ^C2.129: [GC2.129: [ParNew: 293085K->29284K(306688K), 0.0218880 secs]
>>>>> 865240K->604166K(6257408K), 0.0219350 secs] [Times: user=0.09 sys=0.00,
>>>>> real=0.02 secs]
>>>>> Heap
>>>>> par new generation total 306688K, used 40135K [0x000000067ae00000,
>>>>> 0x000000068fac0000, 0x000000068fac0000)
>>>>> eden space 272640K, 3% used [0x000000067ae00000,
>>>>> 0x000000067b898a78, 0x000000068b840000)
>>>>> from space 34048K, 86% used [0x000000068d980000, 0x000000068f619320,
>>>>> 0x000000068fac0000)
>>>>> to space 34048K, 0% used [0x000000068b840000, 0x000000068b840000,
>>>>> 0x000000068d980000)
>>>>> concurrent mark-sweep generation total 5950720K, used 574881K
>>>>> [0x000000068fac0000, 0x00000007fae00000, 0x00000007fae00000)
>>>>> concurrent-mark-sweep perm gen total 21248K, used 2435K
>>>>> [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
>>>>>
>>>>>
>>>>>> Recently we started seeing long ParNewGC pauses when starting up Kafka
>>>>>> that were causing session timeouts:
>>>>>>
>>>>>> [2015-04-24 13:26:23,244] INFO 0 successfully elected as leader
>>>>>> (kafka.server.ZookeeperLeaderElector)
>>>>>> 2.111: [GC (Allocation Failure) 2.111: [ParNew:
>>>>>> 136320K->10236K(153344K), 0.0235777 secs] 648320K->522236K(2080128K),
>>>>>> 0.0237092 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]
>>>>>> 2.599: [GC (Allocation Failure) 2.599: [ParNew:
>>>>>> 146556K->3201K(153344K),
>>>>>> 9.1514626 secs] 658556K->519191K(2080128K), 9.1515757 secs] [Times:
>>>>>> user=18.25 sys=0.01, real=9.15 secs]
>>>>>> [2015-04-24 13:26:33,443] INFO New leader is 0
>>>>>> (kafka.server.ZookeeperLeaderElector$LeaderChangeListener)
>>>>>>
>>>>>> After much investigation I found that the trigger was the
>>>>>> allocation of
>>>>>> a 500M static object early in the Kafka startup code. It of course
>>>>>> makes no sense (to me) that the allocation of a single large static
>>>>>> object in Old memory would impact ParNew collections, but, testing
>>>>>> here
>>>>>> indicates that it does. I have created an Oracle bug report, but,
>>>>>> it is
>>>>>> still under investigation.
>>>>>>
>>>>>> I have reproduced the problem with a simple application on several
>>>>>> Linux
>>>>>> platforms including an EC2 instance (and last night a Win 7
>>>>>> laptop) and
>>>>>> the following JREs:
>>>>>>
>>>>>> OpenJDK: 6, 7, and 8
>>>>>> Oracle: 7 and 8
>>>>>>
>>>>>> Oracle 6 does not seem to have an issue. All its ParNewGC times are
>>>>>> small.
>>>>>>
>>>>>> Here is the simple program that demonstrates the issue (at least
>>>>>> everywhere I have tried it):
>>>>>>
>>>>>> import java.util.ArrayList;
>>>>>>
>>>>>> public class LongParNewPause {
>>>>>>
>>>>>> static byte[] bigStaticObject;
>>>>>>
>>>>>> public static void main(String[] args) throws Exception {
>>>>>> int bigObjSize = args.length > 0 ? Integer.parseInt(args[0])
>>>>>> : 500 * 1024 * 1024;
>>>>>> int littleObjSize = args.length > 1 ? Integer.parseInt(args[1])
>>>>>> : 100;
>>>>>> int saveFraction = args.length > 2 ? Integer.parseInt(args[2])
>>>>>> : 10;
>>>>>>
>>>>>> bigStaticObject = new byte[bigObjSize];
>>>>>>
>>>>>> ArrayList<byte[]> holder = new ArrayList<byte[]>();
>>>>>>
>>>>>> int i = 0;
>>>>>> while (true) {
>>>>>> byte[] local = new byte[littleObjSize];
>>>>>> if (i++ % saveFraction == 0) {
>>>>>> holder.add(local);
>>>>>> }
>>>>>> }
>>>>>> }
>>>>>> }
>>>>>>
>>>>>> I run it with the following options:
>>>>>>
>>>>>> -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails
>>>>>> -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx2G -Xms2G
>>>>>>
>>>>>> Note that I have not seen the issue with 1G heaps. 4G heaps also
>>>>>> exhibit the issue (as do heaps as small as 1.2G). Bigger heaps
>>>>>> seem to
>>>>>> aggrevate the problem.
>>>>>>
>>>>>> Here is some sample output:
>>>>>>
>>>>>> 0.321: [GC (Allocation Failure) 0.321: [ParNew:
>>>>>> 272640K->27329K(306688K), 0.0140537 secs] 784640K->539329K(2063104K),
>>>>>> 0.0141584 secs] [Times: user=0.05 sys=0.02, real=0.02 secs]
>>>>>> 0.368: [GC (Allocation Failure) 0.368: [ParNew:
>>>>>> 299969K->34048K(306688K), 0.7655383 secs] 811969K->572321K(2063104K),
>>>>>> 0.7656172 secs] [Times: user=2.89 sys=0.02, real=0.77 secs]
>>>>>> 1.165: [GC (Allocation Failure) 1.165: [ParNew:
>>>>>> 306688K->34048K(306688K), 13.8395969 secs] 844961K->599389K(2063104K),
>>>>>> 13.8396650 secs] [Times: user=54.38 sys=0.05, real=13.84 secs]
>>>>>> 15.036: [GC (Allocation Failure) 15.036: [ParNew:
>>>>>> 306688K->34048K(306688K), 0.0287254 secs] 872029K->628028K(2063104K),
>>>>>> 0.0287876 secs] [Times: user=0.08 sys=0.01, real=0.03 secs]
>>>>>> 15.096: [GC (Allocation Failure) 15.096: [ParNew:
>>>>>> 306688K->34048K(306688K), 0.0340727 secs] 900668K->657717K(2063104K),
>>>>>> 0.0341386 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
>>>>>> ...
>>>>>>
>>>>>> Even stranger is the fact that the problem seems to be limited to
>>>>>> objects in the range of about 480M to 512M. Specifically:
>>>>>>
>>>>>> [ 503316465 , 536870384 ]
>>>>>>
>>>>>> Values outside this range appear to be OK. Playing with the other
>>>>>> input
>>>>>> parameters (size of the small objects and the fraction that are
>>>>>> retained) can modify the system behavior:
>>>>>>
>>>>>> - Increase the length of the pauses - I have seen pauses of over a
>>>>>> minute my testing.
>>>>>> - Cause the pause times to steadily increase over many ParNewGC
>>>>>> cycles.
>>>>>>
>>>>>> During the pauses the CPUs seem to peg 100% (no waiting on resources).
>>>>>>
>>>>>> Anyone have any thoughts? I would be very interested to know if
>>>>>> anyone
>>>>>> else can reproduce the issue? Other engineers here have been able to.
>
>
> ------------------------------------------------------------------------
>
> This email and any attachments may contain confidential and privileged
> material for the sole use of the intended recipient. Any review,
> copying, or distribution of this email (or any attachments) by others is
> prohibited. If you are not the intended recipient, please contact the
> sender immediately and permanently delete this email and any
> attachments. No employee or agent of TiVo Inc. is authorized to conclude
> any binding agreement on behalf of TiVo Inc. by email. Binding
> agreements with TiVo Inc. may only be made by a signed written agreement.
More information about the hotspot-gc-dev
mailing list