question of ParNewGeneration::real_forwardee_slow

[Thomas Schatzl]

On 9/12/19 5:41 AM, Yan Gang wrote:
> hi Thomas:
> 
> Thanks you reply!
> 
> Follows is full jvm option:
> -Xms6G -Xmx6G -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=512M 
> -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly 
> -XX:CMSInitiatingOccupancyFraction=80 -XX:+HeapDumpOnOutOfMemoryError 
> -verbose:gc -Xloggc:/data/gc.log -XX:+UnlockCommercialFeatures 
> -XX:+FlightRecorder 
> -XX:StartFlightRecording=delay=60s,duration=1h,settings=profile,filename=/data/flight.jfr 
> -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime 
> -XX:PrintFLSStatistics=2 -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
> -XX:+PrintGCDateStamps -XX:-UseParNewGC -XX:ParallelGCThreads=32 
> -XX:+TraceReferenceGC -XX:+TraceScavenge -XX:MaxTenuringThreshold=1 
> -Dcom.sun.management.jmxremote.port=7091 
> -Dcom.sun.management.jmxremote.authenticate=false 
> -Dcom.sun.management.jmxremote.ssl=false gmcf-pmc-web-1.4.0.jar
> 
> JDK version: Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed 
> mode)
> 16C64G
> I check gc.log:
> 2019-09-10T17:42:30.071+0800: 5683.360: [GC (Allocation Failure) 
> 2019-09-10T17:42:30.071+0800: 5683.361: [ParNew: 
> 897542K->13611K(996800K), 0.0213537 secs] 1040925K->157022K(6180736K), 
> 0.0219481 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]
> 2019-09-10T17:42:35.716+0800: 5689.005: [GC (Allocation Failure) 
> 2019-09-10T17:42:35.717+0800: 5689.006: [ParNew: 
> 899691K->7416K(996800K), 4.6872684 secs] 1043102K->156944K(6180736K), 
> 4.6880854 secs] [Times: user=3.76 sys=1.99, real=4.69 secs]
> 2019-09-10T17:42:47.524+0800: 5700.813: [GC (Allocation Failure) 
> 2019-09-10T17:42:47.524+0800: 5700.813: [ParNew: 
> 893496K->3500K(996800K), 0.0396484 secs] 1043024K->153075K(6180736K), 
> 0.0406422 secs] [Times: user=0.52 sys=0.00, real=0.04 secs]
> 
> Maybe big object cause long ParNew GC?

I would check the following:

- do you really need 32 threads? Afaics the amount of data actually 
touched during GC is like 20MB / GC. It makes sense that these 32 
threads are fighting to evacuate these 20MB, potentially leading to the 
reported stalls.

Decreasing the number of parallel GC threads may help.

Contradictory to your setting of ParallelGCThreads=32, you try disable 
parallel evacuation anyway (-XX:-UseParNewGC), which looks weird because 
the user/real time ratio indicates that indeed parallel evacuation is 
going on. Potentially manually setting ParallelGCThreads after 
-XX:-UseParnewGC) re-enables ParNew.

Not sure if this is what you want; but I would look at the suggestion 
below first.

 > 2019-09-10T17:42:35.717+0800: 5689.006: [ParNew:
 > 899691K->7416K(996800K), 4.6872684 secs] 1043102K->156944K(6180736K),
 > 4.6880854 secs] [Times: user=3.76 sys=1.99, real=4.69 secs]

Whatever causes the high sys time may be the actual cause for your 
troubles. Did you try the setup recommendations outlined in the tuning 
guide [0]?

I.e. disable THP, and move the log file to a separate (ram-)disk? The 
options you used indicate that -XX:+AlwaysPreTouch is not enabled either.
Please also look if some swapping activity might be going on on your 
machine.

Thanks,
   Thomas


[0] 
https://docs.oracle.com/en/java/javase/12/gctuning/garbage-first-garbage-collector-tuning.html#GUID-8D9B2530-E370-4B8B-8ADD-A43674FC6658
> 
> Thanks!
> 
> 
> 
> 
> 
> ----- 回复邮件 -----
> *发信人:*Thomas Schatzl <thomas.schatzl at oracle.com 
> <mailto:thomas.schatzl at oracle.com>>
> *收信人:*"Yan Gang" <yangang at ec.com.cn 
> <mailto:yangang at ec.com.cn>>,"hotspot-gc-use" 
> <hotspot-gc-use at openjdk.java.net <mailto:hotspot-gc-use at openjdk.java.net>>
> *时  间:*2019年09月11日 19时57分35秒
> *主  题:*Re: question of ParNewGeneration::real_forwardee_slow
> 
> 
>     Hi,
> 
>     On Wed, 2019-09-11 at 17:08 +0000, Yan Gang wrote:
>      > hi all:
>      > I run 100 threads performance test, use perf top display:
>      >
>      > 71.13% libjvm.so [.]
>      > ParNewGeneration::real_forwardee_slow
>      >
>      > ParNewGeneration::real_forwardee_slow waste some CPU time. I search
>      > google
>      >
>      > ParNewGeneration::real_forwardee_slow belong
>      > of parNewGeneration.cpp, also is JDK bug:
>      > https://bugs.openjdk.java.net/browse/JDK-7171273.
> 
>     The referenced CR only says that this busy-loop is inefficient cpu-
>     wise, not that waiting for another thread should be made substantially
>     faster :)
> 
>     The other problem is that the waste_some_time() is probably completely
>     optimized away with current compilers (constant folded), so hammering
>     that cacheline (with reads) quite a bit. (I believe that there is a CR
>     for that as well somewhere, but maybe we haven't because of CMS
>     obsolescence).
> 
>     If that real_forwardee_slow() method shows up a lot, *maybe* the amount
>     of parallel gc threads used is too high, i.e. threads stepping on each
>     other's toes all the time.
> 
>      > replaced to G1?
> 
>     Our (Oracle's) general advice when having problems with CMS is to try
>     G1, but recent JDKs ship with other GCs that may be suitable to your
>     application (ZGC, Shenandoah, potentially Parallel GC).
> 
>     CMS is on the way out in _future_ releases (see _draft_ JEP
>     https://openjdk.java.net/jeps/8229049). We at Oracle recommend looking
>     into alternatives.
> 
>     Thanks,
>     Thomas
> 
>