Blocks :
|
|
Relates :
|
|
Relates :
|
|
Relates :
|
Vitaly Davidovich posted about this issue here: https://mail.openjdk.java.net/pipermail/hotspot-runtime-dev/2019-June/034706.html with the subject line of "Increased safepoint cleanup tasks in Java 11 (vs 8)" The '-XX:MonitorUsedDeflationThreshold=NN' experimental option was introduced via JDK-8181859 in JDK10. This option can inadvertently cause repeated "cleanup" safepoint operations when ObjectMonitor usage is very low. I have created a test program to demo this issue and I'm also including logs from my JDK13 bits to illustrate the issue. The algorithm of the test is simple: - recursively enter N monitors where each is inflated via a wait(1) call - once the N+1 call is made, delay for 10 seconds With 'monitorinflation' logging enabled, check for the cleanup safepoint logging messages. Here are example runs from my macOSX MBP-13: $ java -Xlog:monitorinflation=info MonitorUsedDeflationThresholdTest 20 \ > MonitorUsedDeflationThresholdTest,info,count=20.log 2>&1 The above cmd will create 20 inflated monitors in the test program. Using "monitorinflation=info" logging, here are the messages generated at a safepoint: $ grep 'gMonitorPopulation=' MonitorUsedDeflationThresholdTest,info,count=20.log [0.110s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=96 [0.118s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=96 [0.205s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 [1.210s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 [10.215s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=64 [10.236s][info][monitorinflation] gMonitorPopulation=127 equals chkMonitorPopulation=127 A few things to notice: - The gMonitorFreeCount value goes from 96 -> 32 - This is the log mesg for when the test has almost gotten to the end of the recursive enters: [0.205s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 - about a second later is another safepoint: [1.210s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 - and about 10 seconds after that is the last safepoint before we start shutting down the VM: [10.215s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=64 Here's another example run: $ java -Xlog:monitorinflation=info MonitorUsedDeflationThresholdTest 33 \ > MonitorUsedDeflationThresholdTest,info,count=33.log 2>&1 The above cmd will create 33 inflated monitors in the test program. Using "monitorinflation=info" logging, here are the messages generated at a safepoint: $ grep 'gMonitorPopulation=' MonitorUsedDeflationThresholdTest,info,count=33.log [0.111s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=96 [0.120s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=96 [0.207s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 [1.212s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [2.217s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [3.218s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [4.219s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [5.224s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [6.229s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [7.230s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [8.236s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [9.237s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 [10.237s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=64 [10.258s][info][monitorinflation] gMonitorPopulation=127 equals chkMonitorPopulation=127 A few things to notice: - The gMonitorFreeCount value goes from 96 -> 32 - This is the log mesg for when the test has almost gotten to the end of the recursive enters: [0.207s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=32 - about a second later is another safepoint: [1.212s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 - at this point gMonitorFreeCount has reached 0 because all of the free global monitors have been allocated to per-thread lists. - there will be a "cleanup" safepoint every second after this point where nothing gets freed and put back on the global free list: [9.237s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=0 - At the 10 second point, we've finished the recursive part of the test and unlocked all the inflated monitors: [10.237s][info][monitorinflation] gMonitorPopulation=127, gOmInUseCount=0, gMonitorFreeCount=64 since the gMonitorFreeCount == 64, that means that the main thread (that ran the test) has exited and released all of its monitors to the free list.
|