United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6914402 G1: assert(!is_young_card(cached_ptr),"shouldn't get a card in young region")
JDK-6914402 : G1: assert(!is_young_card(cached_ptr),"shouldn't get a card in young region")

Details
Type:
Bug
Submit Date:
2010-01-06
Status:
Resolved
Updated Date:
2010-04-06
Project Name:
JDK
Resolved Date:
2010-03-02
Component:
hotspot
OS:
generic
Sub-Component:
gc
CPU:
generic
Priority:
P4
Resolution:
Fixed
Affected Versions:
hs17
Fixed Versions:
hs17 (b10)

Related Reports
Backport:
Backport:
Relates:

Sub Tasks

Description
I got the assert (very very infrequently) on a Solaris/x64 as well as a Solaris/sparc Niagara box when running GCBasher as follows:-

-d64 -server -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:+VerifyBeforeGC -XX:+VerifyAfterGC -XX:+VerifyDuringGC -Xmx64m -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+ShowMessageBoxOnError -XX:+PrintCompilation -XX:CICompilerCount=1 -XX:+UseCompressedOops -Xbatch -jar GCBasher.jar -time:300000


170.266: [GC pause (young)170.450:  (initial-mark), 0.18410294 secs]
   [GC concurrent-mark-start]
[Parallel Time: 172.8 ms]
      [Update RS (Start) (ms):  170278.1  170273.1  170272.6  170272.8  170273.4  170272.6  170279.1  170272.7  170272.6  170272.5  170272.8  170273.1  170272.6  170272.6  170272.7  170272.5  170272.9  170272.7  170272.7  170272.6  170272.8  170272.5  170272.6]
      [Update RS (ms):  27.8  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   1.2, Min:   0.0, Max:  27.8]
         [Processed Buffers : 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
          Sum: 1, Avg: 0, Min: 0, Max: 1]
      [Ext Root Scanning (ms):  6.0  1.3  1.0  0.9  1.1  0.9  7.4  0.8  0.7  0.6  0.8  1.0  0.6  0.5  0.5  0.4  0.6  0.4  0.3  0.3  0.3  0.1  0.1
       Avg:   1.2, Min:   0.1, Max:   7.4]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  19.4  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Avg:   0.8, Min:   0.0, Max:  19.4]
      [Object Copy (ms):  118.2  137.2  137.2  137.2  133.0  137.1  132.5  136.9  137.0  137.3  137.0  136.5  137.0  137.5  136.8  137.1  136.7  137.1  136.9  137.4  136.7  137.1  137.1
       Avg: 135.9, Min: 118.2, Max: 137.5]
      [Termination (ms):  0.0  33.0  33.2  33.3  37.3  33.3  31.3  33.6  33.4  33.2  33.2  33.6  33.5  32.9  33.6  33.4  33.4  33.3  33.5  32.9  33.6  33.4  33.3
       Avg:  32.0, Min:   0.0, Max:  37.3]
      [Other:   1.7 ms]
   [Clear CT:   1.3 ms]
   [Cur Clear CC:   0.0 ms]
   [Cum Clear CC:   0.1 ms]
   [Min Clear CC:   0.0 ms]
   [Max Clear CC:   0.0 ms]
   [Avg Clear CC:   0.0 ms]
   [Other:  10.0 ms]
   [ 64M->45M(256M)]
 [Times: user=3.91 sys=0.03, real=0.20 secs]
170.760: [GC concurrent-mark-end, 0.1081481 sec]
170.760: [GC remark, 0.0090474 secs]
 [Times: user=0.07 sys=0.01, real=0.01 secs]
170.770: [GC concurrent-count-start]
170.822: [GC concurrent-count-end, 0.0512969]
171.080: [GC cleanup 63M->29M(256M), 0.0069773 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs]
171.087: [GC concurrent-cleanup-start]
171.093: [GC concurrent-cleanup-end, 0.0053815]
# To suppress the following error report, specify this argument
# after -XX: or in .hotspotrc:  SuppressErrorAt=/concurrentG1Refine.cpp:273
==============================================================================
Unexpected Error
------------------------------------------------------------------------------
Internal Error at concurrentG1Refine.cpp:273, pid=12698, tid=48
Error: assert(!is_young_card(cached_ptr),"shouldn't get a card in young region")

Do you want to debug the problem?

To debug, run 'dbx - 12698'; then switch to thread 48
Enter 'yes' to launch dbx automatically (PATH must include dbx)
Otherwise, press RETURN to abort...
==============================================================================


  [7] ConcurrentG1Refine::cache_insert(this = ???, card_ptr = ???, defer = ???) (optimized), at 0xffffffff7c51a290 (line ~273) in "concurrentG1Refine.cpp"
  [8] HRInto_G1RemSet::concurrentRefineOneCard(this = ???, card_ptr = ???, worker_i = ???) (optimized), at 0xffffffff7c6deb2c (line ~809) in "g1RemSet.cpp"
  [9] RefineCardTableEntryClosure::do_card_ptr(this = ???, card_ptr = ???, worker_i = ???) (optimized), at 0xffffffff7c6b9360 (line ~59) in "g1CollectedHeap.cpp"
  [10] DirtyCardQueue::apply_closure_to_buffer(cl = ???, buf = ???, index = ???, sz = ???, consume = ???, worker_i = ???) (optimized), at 0xffffffff7c624964 (line ~54) in "dirtyCardQueue.cpp"
  [11] DirtyCardQueueSet::apply_closure_to_completed_buffer_helper(this = ???, worker_i = ???, nd = ???) (optimized), at 0xffffffff7c625254 (line ~182) in "dirtyCardQueue.cpp"
  [12] DirtyCardQueueSet::apply_closure_to_completed_buffer(this = ???, worker_i = ???, stop_at = ???, during_pause = ???) (optimized), at 0xffffffff7c625324 (line ~207) in "dirtyCardQueue.cpp"
  [13] ConcurrentG1RefineThread::run(this = ???) (optimized), at 0xffffffff7c51b634 (line ~115) in "concurrentG1RefineThread.cpp"
  [14] java_start(thread_addr = ???) (optimized), at 0xffffffff7cee19c0 (line ~1019) in "os_solaris.cpp"

                                    

Comments
SUGGESTED FIX

A possible fix could be to change the code in cache_insert from:

jbyte* ConcurrentG1Refine::cache_insert(jbyte* card_ptr, bool* defer) {
  int count;
  jbyte* cached_ptr = add_card_count(card_ptr, &count, defer);
  assert(cached_ptr != NULL, "bad cached card ptr");
  assert(!is_young_card(cached_ptr), "shouldn't get a card in young region");

to:

jbyte* ConcurrentG1Refine::cache_insert(jbyte* card_ptr, bool* defer) {
  int count;
  jbyte* cached_ptr = add_card_count(card_ptr, &count, defer);
  assert(cached_ptr != NULL, "bad cached card ptr");
  if (is_young_card(cached_ptr)) {
    // The region containing cached_ptr has been freed during a clean up
    // pause.
    assert(cached_ptr != card_ptr, "shouldn't be");
    // We've just inserted a new card pointer into the card count cache
    // - its count would be zero so we don't want to defer the cleaning
    // of card_ptr.
    assert(defer == false, "deferring non-hot card");
    return NULL;
  }

Then the code in HRInto_G1RemSet::concurrentRefineOneCard will skip the processing of the return value of cache_insert and immediately process the card passed in.
                                     
2010-01-12
EVALUATION

A region containing cards in the hot card cache or card count cache may be freed after a clean up pause (i.e. none of the objects it contains has been marked as live during concurrent marking). If the region is then tagged as young (i.e. it is used as the current allocation region) then when a card in the region is evicted from the current active card caches then this assert will trip.

Filters were added to eliminate cards in young regions that were evicted from the hot card cache. A similar situation can arise with the cards recorded in the card count cache. Thus this assert is invalid and an additional filter on cards evicted from the card count cache is needed.
                                     
2010-02-03
EVALUATION

ChangeSet=http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/deada8912c54,ChangeRequest=6914402
                                     
2010-02-04



Hardware and Software, Engineered to Work Together