IBM Support

IZ22987: FAILURE TO FREE NURSERY RESULTS IN ENDLESS GC CYCLES

Subscribe

You can track all active APARs for this component.

 

APAR status

  • Closed as program error.

Error description

  • Error Message: The application appears to hang when using the
    gencon GC policy and the verbose gc logs indicate endless GC
    cycles are occurring.
    The verbose gc logs report the following repeating events:
     1. A scavenger gc occurs. The scavenge fails and failure of
    type "flipped" and warning with detail "aborted collection" is
    reported.
     2. This is followed by a global gc with percolating_collect
    reason="failed tenure threshold reached".
     3. Another scavenger gc occurs, there are failures to flip and
    the scavenger collection is aborted
    .
    Stack Trace: Sample verbose gc logs when the problem occurs:
    <af type="nursery" id="14851" timestamp="Thu May 08 13:36:53
    2008" intervalms="0.344">
      <minimum requested_bytes="9330216" />
      <time exclusiveaccessms="0.086" />
      <nursery freebytes="8357888" totalbytes="8884224" percent="94"
    />
      <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
        <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <gc type="scavenger" id="14849" totalid="14888"
    intervalms="0.566">
        <flipped objectcount="83" bytes="70012" />
        <tenured objectcount="0" bytes="0" />
        <refs_cleared soft="0" weak="0" phantom="0" />
        <finalization objectsqueued="0" />
        <scavenger tiltratio="72" />
        <nursery freebytes="9416704" totalbytes="9809920"
    percent="95" tenureage="7" />
        <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
          <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
          <loa freebytes="0" totalbytes="0" percent="0" />
        </tenured>
        <time totalms="3.365" />
      </gc>
      <nursery freebytes="86488" totalbytes="9809920" percent="0" />
      <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
        <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <time totalms="3.668" />
    </af>
    <af type="nursery" id="14852" timestamp="Thu May 08 13:36:53
    2008" intervalms="5.525">
      <minimum requested_bytes="24" />
      <time exclusiveaccessms="0.110" />
      <nursery freebytes="0" totalbytes="9809920" percent="0" />
      <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
        <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <gc type="scavenger" id="14850" totalid="14889"
    intervalms="5.763">
        <failed type="flipped" objectcount="1" bytes="9330216" />
        <warning details="aborted collection" />
        <flipped objectcount="102" bytes="71524" />
        <tenured objectcount="0" bytes="0" />
        <refs_cleared soft="0" weak="0" phantom="0" />
        <finalization objectsqueued="0" />
        <scavenger tiltratio="72" />
        <nursery freebytes="0" totalbytes="9809920" percent="0"
    tenureage="8" />
        <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
          <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
          <loa freebytes="0" totalbytes="0" percent="0" />
        </tenured>
        <time totalms="9.774" />
      </gc>
      <nursery freebytes="0" totalbytes="9809920" percent="0" />
      <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
        <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <time totalms="10.131" />
    </af>
    <af type="nursery" id="14853" timestamp="Thu May 08 13:36:53
    2008" intervalms="0.159">
      <minimum requested_bytes="24" />
      <time exclusiveaccessms="0.110" />
      <nursery freebytes="0" totalbytes="9809920" percent="0" />
      <tenured freebytes="146979912" totalbytes="254843904"
    percent="57" >
        <soa freebytes="146979912" totalbytes="254843904"
    percent="57" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <percolating_collect reason="failed tenure threshold reached"
    />
      <gc type="global" id="40" totalid="14890"
    intervalms="597.834">
        <refs_cleared soft="6" threshold="32" weak="0" phantom="0"
    />
        <finalization objectsqueued="4" />
        <timesms mark="117.336" sweep="2.326" compact="0.000"
    total="119.931" />
        <nursery freebytes="406544" totalbytes="9809920" percent="4"
    />
        <tenured freebytes="151696888" totalbytes="254843904"
    percent="59" >
          <soa freebytes="151696888" totalbytes="254843904"
    percent="59" />
          <loa freebytes="0" totalbytes="0" percent="0" />
        </tenured>
      </gc>
      <nursery freebytes="406520" totalbytes="9809920" percent="4"
    />
      <tenured freebytes="151696888" totalbytes="254843904"
    percent="59" >
        <soa freebytes="151696888" totalbytes="254843904"
    percent="59" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <time totalms="120.275" />
    </af>
    <af type="nursery" id="14854" timestamp="Thu May 08 13:36:53
    2008" intervalms="12.284">
      <minimum requested_bytes="24" />
      <time exclusiveaccessms="0.155" />
      <nursery freebytes="0" totalbytes="9809920" percent="0" />
      <tenured freebytes="151696888" totalbytes="254843904"
    percent="59" >
        <soa freebytes="151696888" totalbytes="254843904"
    percent="59" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <gc type="scavenger" id="14851" totalid="14891"
    intervalms="132.965">
        <failed type="flipped" objectcount="1" bytes="9330216" />
        <warning details="aborted collection" />
        <flipped objectcount="99" bytes="71444" />
        <tenured objectcount="0" bytes="0" />
        <refs_cleared soft="0" weak="0" phantom="0" />
        <finalization objectsqueued="0" />
        <scavenger tiltratio="72" />
        <nursery freebytes="0" totalbytes="9809920" percent="0"
    tenureage="8" />
        <tenured freebytes="151696888" totalbytes="254843904"
    percent="59" >
          <soa freebytes="151696888" totalbytes="254843904"
    percent="59" />
          <loa freebytes="0" totalbytes="0" percent="0" />
        </tenured>
        <time totalms="5.025" />
      </gc>
      <nursery freebytes="0" totalbytes="9809920" percent="0" />
      <tenured freebytes="151696888" totalbytes="254843904"
    percent="59" >
        <soa freebytes="151696888" totalbytes="254843904"
    percent="59" />
        <loa freebytes="0" totalbytes="0" percent="0" />
      </tenured>
      <time totalms="5.613" />
    </af>
    .
    

Local fix

  • This issue can be worked around by adding the command line
    option "-Xcompactgc".
    This will cause a compaction of the heap to occur at the end of
    every GC cycle.
    

Problem summary

  • This issue is caused by a problem in the percolate_collect.
    The GC logs reveal that there is an object which is too large to
    be flipped, but the object is not being tenured either. This
    implies that the tenure space is too fragmented to fit the
    object.
    The root cause of the problem is that the percolate_collect is
    not detecting that a compaction is necessary.
    

Problem conclusion

  • This defect will be fixed in:
    6.0.0 SR2
    5.0.0 SR8
    .
    There were two logic errors which were preventing the
    percolate_collect from forcing a compaction of the heap. These
    errors have been fixed.
    .
    To obtain the fix:
    Install build 20080522 or later
    

Temporary fix

Comments

APAR Information

  • APAR number

    IZ22987

  • Reported component name

    J9 COMMON CODE

  • Reported component ID

    620700127

  • Reported release

    600

  • Status

    CLOSED PER

  • PE

    NoPE

  • HIPER

    NoHIPER

  • Special Attention

    NoSpecatt

  • Submitted date

    2008-05-28

  • Closed date

    2008-06-11

  • Last modified date

    2008-06-11

  • APAR is sysrouted FROM one or more of the following:

  • APAR is sysrouted TO one or more of the following:

    IZ23122

Fix information

  • Fixed component name

    J9 COMMON CODE

  • Fixed component ID

    620700127

Applicable component levels

  • R600 PSN

       UP

[{"Business Unit":{"code":"BU048","label":"IBM Software"},"Product":{"code":"SSCVQ3W","label":"Virtual Machine"},"Component":"","ARM Category":[],"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"6.0","Edition":"","Line of Business":{"code":"","label":""}}]

Document Information

Modified date:
11 June 2008