-
Enhancement
-
Resolution: Fixed
-
P4
-
13
-
b06
-
generic
-
generic
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 viaJDK-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.
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
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.
- is blocked by
-
JDK-8259349 -XX:AvgMonitorsPerThreadEstimate=1 does not work right
- Resolved
- relates to
-
JDK-8253064 monitor list simplifications and getting rid of TSM
- Resolved
-
JDK-8332506 SIGFPE In ObjectSynchronizer::is_async_deflation_needed()
- Resolved
-
JDK-8181859 Monitor deflation is not checked in cleanup path
- Resolved
-
JDK-8256304 should MonitorUsedDeflationThreshold be experimental or diagnostic
- Resolved
-
JDK-8305994 Guarantee eventual async monitor deflation
- Resolved
(1 relates to, 2 links to)