ridiculous ParNew pause times

[Vitaly Davidovich]

This is typically caused by one of:

1) heavy swapping (this won't count towards sys time because kernel is not
using cpu while waiting for I/O to complete)
2) oversubscribed machine where gc threads aren't getting enough cpu time
due

Have you looked at stats on the machine when these pauses occur,
specifically around swap activity? Is your machine running multiple JVMs or
any other noisy neighbor apps?

Sent from my phone
On Apr 9, 2014 7:26 AM, "Cornelius Riemenschneider" <cri at itscope.de> wrote:

> Hello,
>
> we've got the following problem with the ParNew collector:
>
> Our log.gc usually looks like this:
>
> 2014-04-09T12:58:02.485+0200: 77357.712: [GC2014-04-09T12:58:02.485+0200:
> 77357.712: [ParNew: 2722925K->100795K(3145728K), 0.3202010 secs]
> 6998057K->4375934K(21495808K), 0.3205670 secs] [Times: user=4.10 sys=0.02,
> real=0.32 secs]
>
> 2014-04-09T12:58:06.256+0200: 77361.483: [GC2014-04-09T12:58:06.257+0200:
> 77361.483: [ParNew: 2722235K->101011K(3145728K), 0.3229910 secs]
> 6997374K->4376165K(21495808K), 0.3233580 secs] [Times: user=4.13 sys=0.02,
> real=0.33 secs]
>
> 2014-04-09T12:58:12.295+0200: 77367.522: [GC2014-04-09T12:58:12.296+0200:
> 77367.522: [ParNew: 2722451K->101057K(3145728K), 0.3215320 secs]
> 6997605K->4376216K(21495808K), 0.3219080 secs] [Times: user=4.12 sys=0.01,
> real=0.32 secs]
>
> 2014-04-09T12:58:18.461+0200: 77373.688: [GC2014-04-09T12:58:18.462+0200:
> 77373.688: [ParNew: 2722497K->2232K(3145728K), 0.2944540 secs]
> 6997656K->4376242K(21495808K), 0.2948280 secs] [Times: user=3.79 sys=0.00,
> real=0.29 secs]
>
> But occasionally we have entries like these:
>
> 2014-04-09T09:56:12.840+0200: 66448.066: [GC2014-04-09T09:56:38.154+0200:
> 66473.381: [ParNew: 3139808K->524288K(3145728K), 0.8355990 secs]
> 6845512K->4585563K(21495808K), 26.1502640 secs] [Times: user=5.59 sys=0.16,
> real=26.16 secs]
>
> 2014-04-09T09:57:09.173+0200: 66504.400: [GC2014-04-09T09:57:24.871+0200:
> 66520.098: [ParNew: 2950573K->488555K(3145728K), 0.1876660 secs]
> 8701082K->6239064K(21495808K), 15.8858250 secs] [Times: user=2.38 sys=0.00,
> real=15.89 secs]
>
> 2014-04-09T12:58:34.661+0200: 77389.888: [GC2014-04-09T12:59:06.390+0200:
> 77421.616: [ParNew: 2623439K->2083K(3145728K), 0.0292270 secs]
> 6997709K->4376490K(21495808K), 31.7578950 secs] [Times: user=0.34 sys=0.02,
> real=31.76 secs]
>
> which I can't explain at all.
>
> The real time of 31.76sec equals a pause of 31.76secs, in which the jvm
> does not respond to user requests, which is obviously bad.
>
> The application is _*very*_ allocation heavy, so generally pauses of
> 0.3sec are okay.
>
> Our GC settings for this server are:
>
> -Xms21g
>
> -Xmx21g
>
> -XX:ReservedCodeCacheSize=256m
>
> -XX:PermSize=256m
>
> -XX:MaxPermSize=768m
>
> -server
>
> -verbose:gc
>
> -Xloggc:log.gc
>
> -XX:+PrintGCDetails
>
> -XX:+PrintGCDateStamps
>
> -XX:+ExplicitGCInvokesConcurrent
>
> -XX:NewRatio=5
>
> -XX:SurvivorRatio=5
>
> -XX:+UseConcMarkSweepGC
>
> -XX:+UseParNewGC
>
> -XX:+UseCMSInitiatingOccupancyOnly
>
> -XX:CMSInitiatingOccupancyFraction=40
>
> -XX:+CMSClassUnloadingEnabled
>
> -XX:+CMSScavengeBeforeRemark
>
> -Dsun.rmi.dgc.client.gcInterval=1209600000
>
> -Dsun.rmi.dgc.server.gcInterval=1209600000
>
>
>
> We run the sun jdk 7u51 on a current debian wheezy.
>
> We previously had issues with long ParNew pauses, but back then, the sys
> time was high, so we concluded that the server was swapping,
>
> which we were able to prevent.
>
> Do you have any idea or further hint at debugging options which might help
> us in finding the issue?
>
>
>
> Regards,
>
> Cornelius Riemenschneider
>
> --
>
> ITscope GmbH
>
> Ludwig-Erhard-Allee 20
>
> 76131 Karlsruhe
>
> Email: cornelius.riemenschneider at itscope.de
>
> https://www.itscope.com
>
> Handelsregister: AG Mannheim, HRB 232782
>
> Sitz der Gesellschaft: Karlsruhe
>
> Geschäftsführer: Alexander Münkel, Benjamin Mund, Stefan Reger
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20140409/d6e7b7da/attachment.html>