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

MonitorUsedDeflationThreshold can cause repeated async deflation requests

    XMLWordPrintable

Details

    • Enhancement
    • Status: Resolved
    • P4
    • Resolution: Fixed
    • 13
    • 17
    • hotspot
    • b06
    • generic
    • generic

    Description

      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.

      Attachments

        Issue Links

          Activity

            People

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

              Dates

                Created:
                Updated:
                Resolved: