Strange Long ParNew GC Pauses (Sample Code Included)

Fri May 8 18:49:18 UTC 2015

This is indeed interesting...

Jesper, did you figure out why (as James seems to note) the problem is seen
in JDK 8 but not in JDK 6 (he's using ParNew in both cases). Also, isn't
the BOT logarithmic, which will allow threads to "quickly" traverse back to
the start of even a large object? Did something change in the BOT that
might have led to what James sees as a regression, or did the range that he
characterizes as a "blind spot" merely move from one place to another?

Unfortunately, I have not been keeping up with the changes in this area and
am not working with JDK 6 code much, so can't offer any clues, but am
surprised that this would be a regression. (I would expect the same
performance pathologies in this code to exist in 6 and forward -- has it
been established conclusively that this is indeed a regression?)

thanks!
-- ramki

On Fri, May 8, 2015 at 6:40 AM, James Lent <jlent at tivo.com> wrote:

>  The explanation of the problem added by Jesper Wilhelmsson on 2015-05-06
> 08:59 to JDK-8079274 is interesting, but, not very satisfying.
>
> 1) The problem affects more than this one specific breakpoint.  It impacts
> objects in at least the range of about 480M to 512M.  The comment "A larger
> object probably triggers some higher level code that are able to skip
> scanning of this part of the memory" does not inspire confidence. It makes
> even more concerned that we do not understand this issue and that there
> could be other triggers.  It seems like "the higher level code" has a 32M
> blind spot.  Further I can create scenarios where the GC code takes
> progressively longer to clear the issue.  Presumably it completes the lower
> block scan during each GC cycle.  Why does it take longer and longer each
> time (my guess is it has something to do with the number of objects moved
> to survivor space).  If I cache 1 in 100 instead of 1 in 10 then there are
> 11 progressively slower ParNewGC (after several fast one) and the issue
> takes minutes to clear:
>
> $ /usr/lib/jvm/java-7-oracle/bin/java -verbose:gc -XX:+PrintGCTimeStamps
> -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx4G -Xms4G
> LongParNewPause 536870384 100 100
> 0.308: [GC0.308: [ParNew: 272640K->3029K(306688K), 0.0113180 secs]
> 796927K->527316K(4160256K), 0.0114040 secs] [Times: user=0.05 sys=0.00,
> real=0.02 secs]
> 0.367: [GC0.367: [ParNew: 275669K->7766K(306688K), 0.0140840 secs]
> 799956K->532053K(4160256K), 0.0141630 secs] [Times: user=0.04 sys=0.01,
> real=0.02 secs]
> 0.430: [GC0.430: [ParNew: 280406K->10057K(306688K), 0.0120810 secs]
> 804693K->534344K(4160256K), 0.0121690 secs] [Times: user=0.05 sys=0.00,
> real=0.02 secs]
> 0.490: [GC0.490: [ParNew: 282697K->15383K(306688K), 0.0128540 secs]
> 806984K->539670K(4160256K), 0.0129390 secs] [Times: user=0.05 sys=0.00,
> real=0.02 secs]
> 0.551: [GC0.551: [ParNew: 288023K->21006K(306688K), 0.0146480 secs]
> 812310K->545294K(4160256K), 0.0147650 secs] [Times: user=0.05 sys=0.01,
> real=0.01 secs]
> 0.613: [GC0.613: [ParNew: 293646K->26805K(306688K), 0.0141250 secs]
> 817934K->551092K(4160256K), 0.0142050 secs] [Times: user=0.05 sys=0.00,
> real=0.01 secs]
> 0.675: [GC0.675: [ParNew: 299445K->24258K(306688K), 0.4816840 secs]
> 823732K->551436K(4160256K), 0.4817620 secs] [Times: user=1.90 sys=0.00,
> real=0.48 secs]
> 1.205: [GC1.205: [ParNew: 296898K->17914K(306688K), 3.4216550 secs]
> 824076K->547788K(4160256K), 3.4217180 secs] [Times: user=13.50 sys=0.00,
> real=3.42 secs]
> 4.674: [GC4.674: [ParNew: 290554K->17433K(306688K), 6.3406820 secs]
> 820428K->550031K(4160256K), 6.3407410 secs] [Times: user=25.00 sys=0.02,
> real=6.34 secs]
> 11.062: [GC11.062: [ParNew: 290073K->17315K(306688K), 10.9493130 secs]
> 822671K->552636K(4160256K), 10.9493890 secs] [Times: user=42.98 sys=0.03,
> real=10.95 secs]
> 22.059: [GC22.059: [ParNew: 289955K->17758K(306688K), 16.0539650 secs]
> 825276K->555798K(4160256K), 16.0540250 secs] [Times: user=62.44 sys=0.09,
> real=16.05 secs]
> 38.161: [GC38.161: [ParNew: 290398K->17745K(306688K), 20.6900820 secs]
> 828438K->558512K(4160256K), 20.6901420 secs] [Times: user=80.79 sys=0.08,
> real=20.69 secs]
> 58.898: [GC58.898: [ParNew: 290385K->21826K(306688K), 24.6781700 secs]
> 831152K->565310K(4160256K), 24.6782710 secs] [Times: user=95.58 sys=0.05,
> real=24.68 secs]
> 83.625: [GC83.625: [ParNew: 294466K->21834K(306688K), 30.3501800 secs]
> 837950K->568044K(4160256K), 30.3502610 secs] [Times: user=115.80 sys=0.11,
> real=30.35 secs]
> 114.022: [GC114.022: [ParNew: 294474K->21836K(306688K), 33.6648800 secs]
> 840684K->570772K(4160256K), 33.6649390 secs] [Times: user=127.38 sys=0.14,
> real=33.67 secs]
> 147.736: [GC147.736: [ParNew: 294476K->18454K(306688K), 38.9828430 secs]
> 843412K->570117K(4160256K), 38.9829040 secs] [Times: user=149.14 sys=0.15,
> real=38.99 secs]
> 186.766: [GC186.766: [ParNew: 291094K->26602K(306688K), 39.8726730 secs]
> 842757K->580977K(4160256K), 39.8727330 secs] [Times: user=156.35 sys=0.11,
> real=39.88 secs]
> 226.686: [GC226.686: [ParNew: 299242K->26612K(306688K), 0.0174470 secs]
> 853617K->583714K(4160256K), 0.0175300 secs] [Times: user=0.06 sys=0.00,
> real=0.02 secs]
>
> 2) The suggestion to use only 1 thread is not acceptable to me.  Use
> parallel GC with one thread?  Further it did not work for me (in fact it
> made things worse).  "user" time does now equal "real" time (and the new
> size is 1/4 as big) so I think the parameter took effect:
>
> $ /usr/lib/jvm/java-8-oracle/bin/java -verbose:gc -XX:+PrintGCTimeStamps
> -XX:+PrintGCDetails -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Xmx4G -Xms4G
> -XX:ParallelGCThreads=1 LongParNewPause 536870384 100 10
> 0.226: [GC (Allocation Failure) 0.226: [ParNew: 68160K->6980K(76672K),
> 0.0489756 secs] 592447K->531267K(4185792K), 0.0490718 secs] [Times:
> user=0.05 sys=0.00, real=0.05 secs]
> 0.291: [GC (Allocation Failure) 0.291: [ParNew: 75140K->8512K(76672K),
> 29.8707281 secs] 599427K->539479K(4185792K), 29.8707954 secs] [Times:
> user=29.80 sys=0.00, real=29.88 secs]
> 30.180: [GC (Allocation Failure) 30.180: [ParNew: 76672K->8093K(76672K),
> 30.6357699 secs] 607639K->545772K(4185792K), 30.6358257 secs] [Times:
> user=30.57 sys=0.00, real=30.63 secs]
> 60.837: [GC (Allocation Failure) 60.837: [ParNew: 76253K->6830K(76672K),
> 69.2115255 secs] 613932K->552169K(4185792K), 69.2115783 secs] [Times:
> user=69.05 sys=0.01, real=69.22 secs]
> 130.068: [GC (Allocation Failure) 130.068: [ParNew: 74990K->8226K(76672K),
> 132.5118903 secs] 620329K->560381K(4185792K), 132.5119459 secs] [Times:
> user=132.21 sys=0.00, real=132.52 secs]
> 262.603: [GC (Allocation Failure) 262.603: [ParNew: 76386K->8512K(76672K),
> 0.0400138 secs] 628541K->568748K(4185792K), 0.0400687 secs] [Times:
> user=0.04 sys=0.00, real=0.04 secs]
>
> 3) Applications should not be expected to tune the GC settings to account
> for the size of one static object.  The connection between the size of this
> object and the GC performance was not easy to even find.  Further the
> parameter ParGCCardsPerStrideChunk is pretty low level and not one I think
> many application developers are familiar with.
>
> Error: VM option 'ParGCCardsPerStrideChunk' 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.
>
> 4) I can not reproduce this issue in Oracle 6.  This appears to be a
> regression.  How can fixing a regression be called an enhancement request?
>
>
>
>
>
>
>
> ------------------------------
>
> 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.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20150508/af60933b/attachment.htm>