Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8226416

MonitorUsedDeflationThreshold can cause repeated async deflation requests

XMLWordPrintable

    • Icon: Enhancement Enhancement
    • Resolution: Fixed
    • Icon: P4 P4
    • 17
    • 13
    • hotspot
    • 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 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.

            dcubed Daniel Daugherty
            dcubed Daniel Daugherty
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: