I modify Java 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=16 -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
Because 16 CPUs on server.
I get gc info:
2019-09-12T14:13:35.011+0800: 29.841: [GC (Allocation Failure) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 630824960
Max Chunk Size: 630824960
Number of Blocks: 1
Av. Block Size: 630824960
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=630824960 frag=0.0000
2019-09-12T14:13:35.011+0800: 29.841: [ParNew: 1090624K->12224K(1226880K), 1.1448622 secs] 1090624K->12224K(6155200K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 630808576
Max Chunk Size: 630808576
Number of Blocks: 1
Av. Block Size: 630808576
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=630808576 frag=0.0000
, 1.1451469 secs] [Times: user=5.04 sys=3.21, real=1.14 secs]
-----------------------------------------------------------------------------------------
2019-09-12T14:14:22.862+0800: 77.692: [GC (Allocation Failure) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 625129454
Max Chunk Size: 625129454
Number of Blocks: 1
Av. Block Size: 625129454
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 871370
Max Chunk Size: 253
Number of Blocks: 26860
Av. Block Size: 32
free=626000824 frag=0.0028
2019-09-12T14:14:22.862+0800: 77.692: [ParNew: 1128207K->25464K(1226880K), 1.7734633 secs] 1165768K->90673K(6155200K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 621665305
Max Chunk Size: 621665305
Number of Blocks: 1
Av. Block Size: 621665305
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 796557
Max Chunk Size: 251
Number of Blocks: 35502
Av. Block Size: 22
free=622461862 frag=0.0026
, 1.7737061 secs] [Times: user=12.92 sys=0.00, real=1.77 secs]
high Number of Blocks means High fragmentation?
next step : disable THP.
Thanks you !
----- 回复邮件 -----
发信人:Thomas Schatzl <thomas.scha...@oracle.com>
收信人:"Yan Gang" <yang...@ec.com.cn>,"hotspot-gc-use" <hotspot-gc-use@openjdk.java.net>
时 间:2019年09月12日 16时56分37秒
主 题:Re: question of ParNewGeneration::real_forwardee_slow
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.scha...@oracle.com
> <mailto:thomas.scha...@oracle.com>>
> *收信人:*"Yan Gang" <yang...@ec.com.cn
> <mailto:yang...@ec.com.cn>>,"hotspot-gc-use"
> <hotspot-gc-use@openjdk.java.net <mailto:hotspot-gc-use@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
> >
> > 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
>
>
_______________________________________________ hotspot-gc-use mailing list hotspot-gc-use@openjdk.java.net https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
