Strange Long ParNew GC Pauses (Sample Code Included)

Srinivas Ramakrishna ysr1729 at gmail.com
Tue May 12 15:51:00 UTC 2015


Hi James --

I'm interested in this problem, although I do not have the spare cycles to pursue this at the moment. Here's an experiment to try... Allocate your large objects, which get tenured. Call a full GC so the remaining objects are tenured; then just allocate objects and drop them. See if the problem you describe still persists. (Basically what you describe, but making sure that there indeed are no references to young objects from tenured ones.)

I'll try and spend some time on this issue and try and reproduce it on 8uxx when I get a few spare cycles, but can't promise anything... As Jesper notes this sounds like an issue with the block offset table data structure that we maintain, and it has had issues in the past with CMS where large free blocks are broken into smaller blocks during allocation and smaller blocks coalesced into larger ones during sweeping -- tracing (timing past a threshold) the related block offset methods, to do with locating the start of the first object on a (dirty) card, would likely shed more light on where the performance pathology arises. I'll update the jira ticket  if/when I find out something useful.

-- Ramki


ysr1729

> On May 12, 2015, at 08:11, James Lent <jlent at tivo.com> wrote:
> 
> This example demonstrates the ParNew GC code running 60 times slower if
> a static object in a certain 32M size range is allocated.  This speed
> change persists in a steady state where no new objects are being moved
> to Tenured memory or even Survivor space - they are all simply discarded
> immediately.  I think this means that there should be no dirty cards
> (once the system hits steady state) and therefore no need to scan the
> memory occupied by the large static object looking for its start (my
> understanding of the card table and its purpose could be incorrect).  I
> would not be surprised to hear that The ParNew code is actually scanning
> the memory every iteration, but, my question would be why?
> 
> The ParNew GC times seem to jump when the first object is moved to
> Tenured memory.  When this first happens I could see this triggering a
> scan of the memory occupied by the large static object, but, once that
> is complete and no more objects are moved to Tenured memory (by this
> example) I would think the need to do so would disappear.  My wild guess
> theory is that static objects of this size are (somehow) causing the
> PerNew GC code to not clear the card table memory properly.
> 
> Here is some output that includes the Tenuring Distribution data:
> 
> $ /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc -XX:+PrintGCTimeStamps
> -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx4G
> -Xms4G -XX:+PrintTenuringDistribution LongParNewPauseNew 536870384
> 0.283: [GC (Allocation Failure) 0.283: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   1:     256368 bytes,     256368 total
> : 272640K->259K(306688K), 0.0149318 secs] 796927K->524547K(4160256K),
> 0.0149900 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
> 0.337: [GC (Allocation Failure) 0.337: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   2:     255872 bytes,     255872 total
> : 272899K->374K(306688K), 0.0134403 secs] 797187K->524661K(4160256K),
> 0.0135111 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]
> 0.385: [GC (Allocation Failure) 0.385: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   3:     255848 bytes,     255848 total
> : 273014K->331K(306688K), 0.0085707 secs] 797301K->524619K(4160256K),
> 0.0086485 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
> 0.432: [GC (Allocation Failure) 0.432: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   4:     255872 bytes,     255872 total
> : 272971K->410K(306688K), 0.0093637 secs] 797259K->524697K(4160256K),
> 0.0094392 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
> 0.477: [GC (Allocation Failure) 0.477: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   5:     255848 bytes,     255848 total
> : 273050K->319K(306688K), 0.0085916 secs] 797337K->524607K(4160256K),
> 0.0086509 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
> 0.521: [GC (Allocation Failure) 0.521: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> - age   6:     255864 bytes,     255864 total
> : 272959K->360K(306688K), 0.0096355 secs] 797247K->524648K(4160256K),
> 0.0097261 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
> 0.566: [GC (Allocation Failure) 0.566: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> : 273000K->0K(306688K), 0.5524753 secs] 797288K->524549K(4160256K),
> 0.5525589 secs] [Times: user=2.15 sys=0.00, real=0.55 secs]
> 1.155: [GC (Allocation Failure) 1.155: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> : 272640K->0K(306688K), 0.6131581 secs] 797189K->524549K(4160256K),
> 0.6132457 secs] [Times: user=2.42 sys=0.00, real=0.62 secs]
> 1.803: [GC (Allocation Failure) 1.803: [ParNew
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> : 272640K->0K(306688K), 0.6350230 secs] 797189K->524549K(4160256K),
> 0.6350981 secs] [Times: user=2.48 sys=0.00, real=0.63 secs]
> 2.475: [GC (Allocation Failure) 2.475: [ParNew^C
> Desired survivor size 17432576 bytes, new threshold 6 (max 6)
> : 272640K->0K(306688K), 0.7487256 secs] 797189K->524549K(4160256K),
> 0.7488073 secs] [Times: user=2.63 sys=0.00, real=0.75 secs]
> Heap
> 
>> Here is a simpler version of a program that triggers a less dramatic
>> version of the issue.  In this program no memory is cached by the
>> application itself (i.e. it places no explicit demands on tenured
>> memory).  Hopefully a simpler example is easier to analyze (it quickly
>> reaches a steady state).  Again:
>> 
>> 1) I can not reproducible with Oracle 6
>> 2) Triggered by static objects in the size range from about 480M to
>> 512M (with longer pauses towards the high end of the range).
>> 
>> public class LongParNewPauseNew {
>> 
>>   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]) : 1000;
>> 
>>       bigStaticObject = new byte[bigObjSize];
>> 
>>       while (true) {
>>           byte[] local = new byte[littleObjSize];
>>       }
>>   }
>> }
>> 
>> With Oracle 8 and static object of size 536870385 there is no issue:
>> 
>> $ /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc
>> -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseParNewGC
>> -XX:+UseConcMarkSweepGC -Xmx4G -Xms4G LongParNewPauseNew 536870385
>> 0.278: [GC (Allocation Failure) 0.278: [ParNew:
>> 272640K->261K(306688K), 0.0063950 secs] 796927K->524548K(4160256K),
>> 0.0065076 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
>> 0.322: [GC (Allocation Failure) 0.322: [ParNew:
>> 272901K->401K(306688K), 0.0056171 secs] 797188K->524689K(4160256K),
>> 0.0056952 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
>> 0.363: [GC (Allocation Failure) 0.363: [ParNew:
>> 273041K->336K(306688K), 0.0057683 secs] 797329K->524624K(4160256K),
>> 0.0058311 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
>> 0.408: [GC (Allocation Failure) 0.408: [ParNew:
>> 272976K->333K(306688K), 0.0066688 secs] 797264K->524621K(4160256K),
>> 0.0067301 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
>> 0.449: [GC (Allocation Failure) 0.449: [ParNew:
>> 272973K->429K(306688K), 0.0057720 secs] 797261K->524717K(4160256K),
>> 0.0058348 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
>> 0.494: [GC (Allocation Failure) 0.494: [ParNew:
>> 273069K->335K(306688K), 0.0062634 secs] 797357K->524623K(4160256K),
>> 0.0063349 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
>> 0.539: [GC (Allocation Failure) 0.539: [ParNew: 272975K->0K(306688K),
>> 0.0070370 secs] 797263K->524549K(4160256K), 0.0070927 secs] [Times:
>> user=0.03 sys=0.00, real=0.01 secs]
>> 0.582: [GC (Allocation Failure) 0.582: [ParNew: 272640K->0K(306688K),
>> 0.0074841 secs] 797189K->524549K(4160256K), 0.0075506 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 0.624: [GC (Allocation Failure) 0.625: [ParNew: 272640K->0K(306688K),
>> 0.0062554 secs] 797189K->524549K(4160256K), 0.0063346 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 0.670: [GC (Allocation Failure) 0.670: [ParNew: 272640K->0K(306688K),
>> 0.0063389 secs] 797189K->524549K(4160256K), 0.0064412 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> ...
>> 30.028: [GC (Allocation Failure) 30.028: [ParNew:
>> 272640K->0K(306688K), 0.0077380 secs] 797189K->524549K(4160256K),
>> 0.0078026 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 30.071: [GC (Allocation Failure) 30.071: [ParNew:
>> 272640K->0K(306688K), 0.0063162 secs] 797189K->524549K(4160256K),
>> 0.0064059 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 30.113: [GC (Allocation Failure) 30.113: [ParNew:
>> 272640K->0K(306688K), 0.0078365 secs] 797189K->524549K(4160256K),
>> 0.0079142 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 30.158: [GC (Allocation Failure) 30.158: [ParNew:
>> 272640K->0K(306688K), 0.0066567 secs] 797189K->524549K(4160256K),
>> 0.0067534 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
>> 30.204: [GC (Allocation Failure) 30.204: [ParNew:
>> 272640K->0K(306688K), 0.0091868 secs] 797189K->524549K(4160256K),
>> 0.0092649 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 
>> With Oracle 8 and static object of 536870384 after a few quick ParNew
>> GCs they level out at a value 60 times more expensive in terms of
>> "real" time ("user" time multiple is worse):
>> 
>> $ /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc
>> -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseParNewGC
>> -XX:+UseConcMarkSweepGC -Xmx4G -Xms4G LongParNewPauseNew 536870384
>> 0.279: [GC (Allocation Failure) 0.279: [ParNew:
>> 272640K->265K(306688K), 0.0102627 secs] 796927K->524552K(4160256K),
>> 0.0103542 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
>> 0.328: [GC (Allocation Failure) 0.328: [ParNew:
>> 272905K->361K(306688K), 0.0086337 secs] 797192K->524649K(4160256K),
>> 0.0086982 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 0.374: [GC (Allocation Failure) 0.374: [ParNew:
>> 273001K->404K(306688K), 0.0087999 secs] 797289K->524692K(4160256K),
>> 0.0088859 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
>> 0.419: [GC (Allocation Failure) 0.419: [ParNew:
>> 273044K->345K(306688K), 0.0097886 secs] 797332K->524632K(4160256K),
>> 0.0098663 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 0.464: [GC (Allocation Failure) 0.464: [ParNew:
>> 272985K->370K(306688K), 0.0109442 secs] 797272K->524658K(4160256K),
>> 0.0110104 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
>> 0.510: [GC (Allocation Failure) 0.510: [ParNew:
>> 273010K->313K(306688K), 0.0103121 secs] 797298K->524601K(4160256K),
>> 0.0103963 secs] [Times: user=0.04 sys=0.00, real=0.00 secs]
>> 0.556: [GC (Allocation Failure) 0.556: [ParNew: 272953K->0K(306688K),
>> 0.5380597 secs] 797241K->524549K(4160256K), 0.5381252 secs] [Times:
>> user=2.13 sys=0.00, real=0.54 secs]
>> 1.129: [GC (Allocation Failure) 1.129: [ParNew: 272640K->0K(306688K),
>> 0.6076693 secs] 797189K->524549K(4160256K), 0.6077654 secs] [Times:
>> user=2.39 sys=0.00, real=0.60 secs]
>> 1.772: [GC (Allocation Failure) 1.772: [ParNew: 272640K->0K(306688K),
>> 0.5950040 secs] 797189K->524549K(4160256K), 0.5950680 secs] [Times:
>> user=2.35 sys=0.01, real=0.59 secs]
>> 2.403: [GC (Allocation Failure) 2.403: [ParNew: 272640K->0K(306688K),
>> 0.6031121 secs] 797189K->524549K(4160256K), 0.6032018 secs] [Times:
>> user=2.37 sys=0.00, real=0.60 secs]
>> ...
>> 34.062: [GC (Allocation Failure) 34.062: [ParNew:
>> 272640K->0K(306688K), 0.6038964 secs] 797189K->524549K(4160256K),
>> 0.6039870 secs] [Times: user=2.36 sys=0.01, real=0.60 secs]
>> 34.701: [GC (Allocation Failure) 34.701: [ParNew:
>> 272640K->0K(306688K), 0.5933985 secs] 797189K->524549K(4160256K),
>> 0.5934782 secs] [Times: user=2.35 sys=0.00, real=0.59 secs]
>> 35.330: [GC (Allocation Failure) 35.331: [ParNew:
>> 272640K->0K(306688K), 0.6028332 secs] 797189K->524549K(4160256K),
>> 0.6029144 secs] [Times: user=2.37 sys=0.00, real=0.60 secs]
>> 35.969: [GC (Allocation Failure) 35.969: [ParNew:
>> 272640K->0K(306688K), 0.6073454 secs] 797189K->524549K(4160256K),
>> 0.6074109 secs] [Times: user=2.37 sys=0.01, real=0.61 secs]
>> 36.611: [GC (Allocation Failure) 36.611: [ParNew:
>> 272640K->0K(306688K), 0.5984771 secs] 797189K->524549K(4160256K),
>> 0.5985538 secs] [Times: user=2.37 sys=0.00, real=0.60 secs]
>> 37.245: [GC (Allocation Failure) 37.245: [ParNew^C:
>> 272640K->0K(306688K), 0.6040984 secs] 797189K->524549K(4160256K),
>> 0.6041841 secs] [Times: user=2.37 sys=0.00, real=0.61 secs]
>> 
>> If while running with a static object of size 536870384 I connect with
>> VisualVM I can trigger steadily increasing ParNew times (there is no
>> noticeable impact with the one byte larger object).
>> 
>> $ /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc
>> -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseParNewGC
>> -XX:+UseConcMarkSweepGC -Xmx4G -Xms4G LongParNewPauseNew
>> 5368703840.278: [GC (Allocation Failure) 0.278: [ParNew:
>> 272640K->273K(306688K), 0.0103594 secs] 796927K->524560K(4160256K),
>> 0.0104768 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]
>> 0.325: [GC (Allocation Failure) 0.325: [ParNew:
>> 272913K->417K(306688K), 0.0092965 secs] 797200K->524705K(4160256K),
>> 0.0093772 secs] [Times: user=0.04 sys=0.00, real=0.02 secs]
>> 0.372: [GC (Allocation Failure) 0.373: [ParNew:
>> 273057K->324K(306688K), 0.0090116 secs] 797345K->524611K(4160256K),
>> 0.0090913 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
>> 0.417: [GC (Allocation Failure) 0.417: [ParNew:
>> 272964K->423K(306688K), 0.0087881 secs] 797251K->524711K(4160256K),
>> 0.0088554 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
>> 0.461: [GC (Allocation Failure) 0.461: [ParNew:
>> 273063K->349K(306688K), 0.0092834 secs] 797351K->524637K(4160256K),
>> 0.0093573 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
>> 0.507: [GC (Allocation Failure) 0.507: [ParNew:
>> 272989K->307K(306688K), 0.0106442 secs] 797277K->524594K(4160256K),
>> 0.0107276 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
>> 0.555: [GC (Allocation Failure) 0.555: [ParNew: 272947K->0K(306688K),
>> 0.5496337 secs] 797234K->524549K(4160256K), 0.5496888 secs] [Times:
>> user=2.11 sys=0.00, real=0.54 secs]
>> 1.140: [GC (Allocation Failure) 1.140: [ParNew: 272640K->0K(306688K),
>> 0.6094898 secs] 797189K->524549K(4160256K), 0.6095588 secs] [Times:
>> user=2.38 sys=0.00, real=0.61 secs]
>> 1.785: [GC (Allocation Failure) 1.785: [ParNew: 272640K->0K(306688K),
>> 0.6220573 secs] 797189K->524549K(4160256K), 0.6221189 secs] [Times:
>> user=2.40 sys=0.00, real=0.63 secs]
>> [Connect with VisualVM About here]
>> 2.442: [GC (Allocation Failure) 2.442: [ParNew: 272640K->4K(306688K),
>> 0.5985618 secs] 797189K->524553K(4160256K), 0.5986316 secs] [Times:
>> user=2.36 sys=0.00, real=0.60 secs]
>> 3.078: [GC (Allocation Failure) 3.078: [ParNew: 272644K->4K(306688K),
>> 0.5999697 secs] 797193K->524553K(4160256K), 0.6000559 secs] [Times:
>> user=2.36 sys=0.00, real=0.60 secs]
>> 3.714: [GC (Allocation Failure) 3.714: [ParNew: 272644K->4K(306688K),
>> 0.8694936 secs] 797193K->524553K(4160256K), 0.8695693 secs] [Times:
>> user=3.06 sys=0.01, real=0.86 secs]
>> 4.619: [GC (Allocation Failure) 4.619: [ParNew: 272644K->4K(306688K),
>> 0.6437319 secs] 797193K->524553K(4160256K), 0.6438180 secs] [Times:
>> user=2.47 sys=0.00, real=0.64 secs]
>> 5.299: [GC (Allocation Failure) 5.299: [ParNew:
>> 272644K->309K(306688K), 0.6084965 secs] 797193K->524858K(4160256K),
>> 0.6085572 secs] [Times: user=2.40 sys=0.00, real=0.61 secs]
>> 5.944: [GC (Allocation Failure) 5.944: [ParNew:
>> 272949K->669K(306688K), 0.6163285 secs] 797498K->525218K(4160256K),
>> 0.6163989 secs] [Times: user=2.42 sys=0.00, real=0.62 secs]
>> 6.600: [GC (Allocation Failure) 6.600: [ParNew:
>> 273309K->1042K(306688K), 0.6244556 secs] 797858K->525592K(4160256K),
>> 0.6245076 secs] [Times: user=2.43 sys=0.00, real=0.62 secs]
>> 7.260: [GC (Allocation Failure) 7.260: [ParNew:
>> 273682K->1398K(306688K), 0.5966316 secs] 798232K->525948K(4160256K),
>> 0.5966946 secs] [Times: user=2.35 sys=0.00, real=0.60 secs]
>> 7.892: [GC (Allocation Failure) 7.892: [ParNew:
>> 274038K->1654K(306688K), 0.6107431 secs] 798588K->526203K(4160256K),
>> 0.6108187 secs] [Times: user=2.38 sys=0.00, real=0.61 secs]
>> 8.547: [GC (Allocation Failure) 8.547: [ParNew:
>> 274294K->1887K(306688K), 0.6200231 secs] 798843K->526436K(4160256K),
>> 0.6200900 secs] [Times: user=2.43 sys=0.00, real=0.62 secs]
>> 9.204: [GC (Allocation Failure) 9.204: [ParNew:
>> 274527K->1822K(306688K), 1.2716345 secs] 799076K->526689K(4160256K),
>> 1.2716863 secs] [Times: user=5.01 sys=0.00, real=1.28 secs]
>> 10.512: [GC (Allocation Failure) 10.512: [ParNew:
>> 274462K->1419K(306688K), 2.7103616 secs] 799329K->526556K(4160256K),
>> 2.7104158 secs] [Times: user=8.89 sys=0.01, real=2.71 secs]
>> 13.272: [GC (Allocation Failure) 13.272: [ParNew:
>> 274059K->988K(306688K), 2.7453068 secs] 799196K->526357K(4160256K),
>> 2.7453928 secs] [Times: user=10.81 sys=0.01, real=2.75 secs]
>> 16.056: [GC (Allocation Failure) 16.056: [ParNew:
>> 273628K->795K(306688K), 3.4620199 secs] 798997K->526425K(4160256K),
>> 3.4620805 secs] [Times: user=13.42 sys=0.01, real=3.46 secs]
>> 19.557: [GC (Allocation Failure) 19.557: [ParNew:
>> 273435K->496K(306688K), 3.5968764 secs] 799065K->526224K(4160256K),
>> 3.5969426 secs] [Times: user=14.18 sys=0.02, real=3.60 secs]
>> 23.194: [GC (Allocation Failure) 23.194: [ParNew:
>> 273136K->442K(306688K), 3.9195231 secs] 798864K->526305K(4160256K),
>> 3.9195804 secs] [Times: user=15.45 sys=0.00, real=3.91 secs]
>> 27.151: [GC (Allocation Failure) 27.151: [ParNew:
>> 273082K->228K(306688K), 4.1905771 secs] 798945K->526211K(4160256K),
>> 4.1906422 secs] [Times: user=16.53 sys=0.01, real=4.20 secs]
>> 31.379: [GC (Allocation Failure) 31.379: [ParNew^C:
>> 272868K->149K(306688K), 4.2777952 secs] 798851K->526151K(4160256K),
>> 4.2778607 secs] [Times: user=16.85 sys=0.01, real=4.28 secs]
> 
> 
> ________________________________
> 
> 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