Strange Long ParNew GC Pauses (Sample Code Included)
James Lent
jlent at tivo.com
Mon May 11 16:12:52 UTC 2015
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