6937142: G1: improvements to debugging output (S-M)

Summary: Various fixes to the G1 debugging output.
Reviewed-by: johnc, iveresov

src/share/vm/gc_implementation/g1/concurrentMark.cpp

@@ -767,7 +767,8 @@ void ConcurrentMark::checkpointRootsInitialPre() {
   _has_aborted = false;
 
   if (G1PrintReachableAtInitialMark) {
-    print_reachable(true, "before");
+    print_reachable("at-cycle-start",
+                    true /* use_prev_marking */, true /* all */);
   }
 
   // Initialise marking structures. This has to be done in a STW phase.
@@ -1979,19 +1980,21 @@ void ConcurrentMark::checkpointRootsFinalWork() {
 
 #ifndef PRODUCT
 
-class ReachablePrinterOopClosure: public OopClosure {
+class PrintReachableOopClosure: public OopClosure {
 private:
   G1CollectedHeap* _g1h;
   CMBitMapRO*      _bitmap;
   outputStream*    _out;
   bool             _use_prev_marking;
+  bool             _all;
 
 public:
-  ReachablePrinterOopClosure(CMBitMapRO*   bitmap,
+  PrintReachableOopClosure(CMBitMapRO*   bitmap,
                            outputStream* out,
-                             bool          use_prev_marking) :
+                           bool          use_prev_marking,
+                           bool          all) :
     _g1h(G1CollectedHeap::heap()),
-    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking) { }
+    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking), _all(all) { }
 
   void do_oop(narrowOop* p) { do_oop_work(p); }
   void do_oop(      oop* p) { do_oop_work(p); }
@@ -2001,9 +2004,11 @@ public:
     const char* str = NULL;
     const char* str2 = "";
 
-    if (!_g1h->is_in_g1_reserved(obj))
-      str = "outside G1 reserved";
-    else {
+    if (obj == NULL) {
+      str = "";
+    } else if (!_g1h->is_in_g1_reserved(obj)) {
+      str = " O";
+    } else {
       HeapRegion* hr  = _g1h->heap_region_containing(obj);
       guarantee(hr != NULL, "invariant");
       bool over_tams = false;
@@ -2012,74 +2017,67 @@ public:
       } else {
         over_tams = hr->obj_allocated_since_next_marking(obj);
       }
+      bool marked = _bitmap->isMarked((HeapWord*) obj);
 
       if (over_tams) {
-        str = "over TAMS";
-        if (_bitmap->isMarked((HeapWord*) obj)) {
+        str = " >";
+        if (marked) {
           str2 = " AND MARKED";
         }
-      } else if (_bitmap->isMarked((HeapWord*) obj)) {
-        str = "marked";
+      } else if (marked) {
+        str = " M";
       } else {
-        str = "#### NOT MARKED ####";
+        str = " NOT";
       }
     }
 
-    _out->print_cr("    "PTR_FORMAT" contains "PTR_FORMAT" %s%s",
+    _out->print_cr("  "PTR_FORMAT": "PTR_FORMAT"%s%s",
                    p, (void*) obj, str, str2);
   }
 };
 
-class ReachablePrinterClosure: public BitMapClosure {
-private:
-  CMBitMapRO*   _bitmap;
-  outputStream* _out;
-  bool          _use_prev_marking;
-
-public:
-  ReachablePrinterClosure(CMBitMapRO*   bitmap,
-                          outputStream* out,
-                          bool          use_prev_marking) :
-    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking) { }
-
-  bool do_bit(size_t offset) {
-    HeapWord* addr = _bitmap->offsetToHeapWord(offset);
-    ReachablePrinterOopClosure oopCl(_bitmap, _out, _use_prev_marking);
-
-    _out->print_cr("  obj "PTR_FORMAT", offset %10d (marked)", addr, offset);
-    oop(addr)->oop_iterate(&oopCl);
-    _out->print_cr("");
-
-    return true;
-  }
-};
-
-class ObjInRegionReachablePrinterClosure : public ObjectClosure {
+class PrintReachableObjectClosure : public ObjectClosure {
 private:
   CMBitMapRO*   _bitmap;
   outputStream* _out;
   bool          _use_prev_marking;
+  bool          _all;
+  HeapRegion*   _hr;
 
 public:
-  ObjInRegionReachablePrinterClosure(CMBitMapRO*   bitmap,
+  PrintReachableObjectClosure(CMBitMapRO*   bitmap,
                               outputStream* out,
-                                     bool          use_prev_marking) :
-    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking) { }
+                              bool          use_prev_marking,
+                              bool          all,
+                              HeapRegion*   hr) :
+    _bitmap(bitmap), _out(out),
+    _use_prev_marking(use_prev_marking), _all(all), _hr(hr) { }
 
   void do_object(oop o) {
-    ReachablePrinterOopClosure oopCl(_bitmap, _out, _use_prev_marking);
+    bool over_tams;
+    if (_use_prev_marking) {
+      over_tams = _hr->obj_allocated_since_prev_marking(o);
+    } else {
+      over_tams = _hr->obj_allocated_since_next_marking(o);
+    }
+    bool marked = _bitmap->isMarked((HeapWord*) o);
+    bool print_it = _all || over_tams || marked;
 
-    _out->print_cr("  obj "PTR_FORMAT" (over TAMS)", (void*) o);
+    if (print_it) {
+      _out->print_cr(" "PTR_FORMAT"%s",
+                     o, (over_tams) ? " >" : (marked) ? " M" : "");
+      PrintReachableOopClosure oopCl(_bitmap, _out, _use_prev_marking, _all);
       o->oop_iterate(&oopCl);
-    _out->print_cr("");
+    }
   }
 };
 
-class RegionReachablePrinterClosure : public HeapRegionClosure {
+class PrintReachableRegionClosure : public HeapRegionClosure {
 private:
   CMBitMapRO*   _bitmap;
   outputStream* _out;
   bool          _use_prev_marking;
+  bool          _all;
 
 public:
   bool doHeapRegion(HeapRegion* hr) {
@@ -2094,22 +2092,35 @@ public:
     }
     _out->print_cr("** ["PTR_FORMAT", "PTR_FORMAT"] top: "PTR_FORMAT" "
                    "TAMS: "PTR_FORMAT, b, e, t, p);
-    _out->print_cr("");
+    _out->cr();
+
+    HeapWord* from = b;
+    HeapWord* to   = t;
 
-    ObjInRegionReachablePrinterClosure ocl(_bitmap, _out, _use_prev_marking);
-    hr->object_iterate_mem_careful(MemRegion(p, t), &ocl);
+    if (to > from) {
+      _out->print_cr("Objects in ["PTR_FORMAT", "PTR_FORMAT"]", from, to);
+      _out->cr();
+      PrintReachableObjectClosure ocl(_bitmap, _out,
+                                      _use_prev_marking, _all, hr);
+      hr->object_iterate_mem_careful(MemRegion(from, to), &ocl);
+      _out->cr();
+    }
 
     return false;
   }
 
-  RegionReachablePrinterClosure(CMBitMapRO*   bitmap,
+  PrintReachableRegionClosure(CMBitMapRO*   bitmap,
                               outputStream* out,
-                                bool          use_prev_marking) :
-    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking) { }
+                              bool          use_prev_marking,
+                              bool          all) :
+    _bitmap(bitmap), _out(out), _use_prev_marking(use_prev_marking), _all(all) { }
 };
 
-void ConcurrentMark::print_reachable(bool use_prev_marking, const char* str) {
-  gclog_or_tty->print_cr("== Doing reachable object dump... ");
+void ConcurrentMark::print_reachable(const char* str,
+                                     bool use_prev_marking,
+                                     bool all) {
+  gclog_or_tty->cr();
+  gclog_or_tty->print_cr("== Doing heap dump... ");
 
   if (G1PrintReachableBaseFile == NULL) {
     gclog_or_tty->print_cr("  #### error: no base file defined");
@@ -2144,19 +2155,14 @@ void ConcurrentMark::print_reachable(bool use_prev_marking, const char* str) {
   out->print_cr("-- USING %s", (use_prev_marking) ? "PTAMS" : "NTAMS");
   out->cr();
 
-  RegionReachablePrinterClosure rcl(bitmap, out, use_prev_marking);
-  out->print_cr("--- ITERATING OVER REGIONS WITH TAMS < TOP");
+  out->print_cr("--- ITERATING OVER REGIONS");
   out->cr();
+  PrintReachableRegionClosure rcl(bitmap, out, use_prev_marking, all);
   _g1h->heap_region_iterate(&rcl);
   out->cr();
 
-  ReachablePrinterClosure cl(bitmap, out, use_prev_marking);
-  out->print_cr("--- ITERATING OVER MARKED OBJECTS ON THE BITMAP");
-  out->cr();
-  bitmap->iterate(&cl);
-  out->cr();
-
   gclog_or_tty->print_cr("  done");
+  gclog_or_tty->flush();
 }
 
 #endif // PRODUCT

src/share/vm/gc_implementation/g1/concurrentMark.hpp

@@ -652,11 +652,24 @@ public:
   // we do nothing.
   void markAndGrayObjectIfNecessary(oop p);
 
-  // This iterates over the marking bitmap (either prev or next) and
-  // prints out all objects that are marked on the bitmap and indicates
-  // whether what they point to is also marked or not. It also iterates
-  // the objects over TAMS (either prev or next).
-  void print_reachable(bool use_prev_marking, const char* str);
+  // It iterates over the heap and for each object it comes across it
+  // will dump the contents of its reference fields, as well as
+  // liveness information for the object and its referents. The dump
+  // will be written to a file with the following name:
+  // G1PrintReachableBaseFile + "." + str. use_prev_marking decides
+  // whether the prev (use_prev_marking == true) or next
+  // (use_prev_marking == false) marking information will be used to
+  // determine the liveness of each object / referent. If all is true,
+  // all objects in the heap will be dumped, otherwise only the live
+  // ones. In the dump the following symbols / abbreviations are used:
+  //   M : an explicitly live object (its bitmap bit is set)
+  //   > : an implicitly live object (over tams)
+  //   O : an object outside the G1 heap (typically: in the perm gen)
+  //   NOT : a reference field whose referent is not live
+  //   AND MARKED : indicates that an object is both explicitly and
+  //   implicitly live (it should be one or the other, not both)
+  void print_reachable(const char* str,
+                       bool use_prev_marking, bool all) PRODUCT_RETURN;
 
   // Clear the next marking bitmap (will be called concurrently).
   void clearNextBitmap();

src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

@@ -2397,8 +2397,8 @@ void G1CollectedHeap::verify(bool allow_dirty,
       print_on(gclog_or_tty, true /* extended */);
       gclog_or_tty->print_cr("");
       if (VerifyDuringGC && G1VerifyDuringGCPrintReachable) {
-        concurrent_mark()->print_reachable(use_prev_marking,
-                                           "failed-verification");
+        concurrent_mark()->print_reachable("at-verification-failure",
+                                           use_prev_marking, false /* all */);
       }
       gclog_or_tty->flush();
     }
@@ -3118,6 +3118,11 @@ void G1CollectedHeap::get_gc_alloc_regions() {
     } else {
       // the region was retained from the last collection
       ++_gc_alloc_region_counts[ap];
+      if (G1PrintHeapRegions) {
+        gclog_or_tty->print_cr("new alloc region %d:["PTR_FORMAT", "PTR_FORMAT"], "
+                               "top "PTR_FORMAT,
+                               alloc_region->hrs_index(), alloc_region->bottom(), alloc_region->end(), alloc_region->top());
+      }
     }
 
     if (alloc_region != NULL) {

src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp

@@ -2942,10 +2942,11 @@ record_concurrent_mark_cleanup_end(size_t freed_bytes,
 void G1CollectorPolicy::
 add_to_collection_set(HeapRegion* hr) {
   if (G1PrintHeapRegions) {
-    gclog_or_tty->print_cr("added region to cset %d:["PTR_FORMAT", "PTR_FORMAT"], "
-                  "top "PTR_FORMAT", young %s",
+    gclog_or_tty->print_cr("added region to cset "
+                           "%d:["PTR_FORMAT", "PTR_FORMAT"], "
+                           "top "PTR_FORMAT", %s",
                            hr->hrs_index(), hr->bottom(), hr->end(),
-                  hr->top(), (hr->is_young()) ? "YES" : "NO");
+                           hr->top(), hr->is_young() ? "YOUNG" : "NOT_YOUNG");
   }
 
   if (_g1->mark_in_progress())

src/share/vm/gc_implementation/g1/heapRegion.cpp

@@ -75,6 +75,16 @@ public:
   virtual void do_oop(narrowOop* p) { do_oop_work(p); }
   virtual void do_oop(      oop* p) { do_oop_work(p); }
 
+  void print_object(outputStream* out, oop obj) {
+#ifdef PRODUCT
+    klassOop k = obj->klass();
+    const char* class_name = instanceKlass::cast(k)->external_name();
+    out->print_cr("class name %s", class_name);
+#else // PRODUCT
+    obj->print_on(out);
+#endif // PRODUCT
+  }
+
   template <class T> void do_oop_work(T* p) {
     assert(_containing_obj != NULL, "Precondition");
     assert(!_g1h->is_obj_dead_cond(_containing_obj, _use_prev_marking),
@@ -90,21 +100,29 @@ public:
           gclog_or_tty->print_cr("----------");
         }
         if (!_g1h->is_in_closed_subset(obj)) {
+          HeapRegion* from = _g1h->heap_region_containing((HeapWord*)p);
           gclog_or_tty->print_cr("Field "PTR_FORMAT
-                        " of live obj "PTR_FORMAT
-                        " points to obj "PTR_FORMAT
-                        " not in the heap.",
-                        p, (void*) _containing_obj, (void*) obj);
+                                 " of live obj "PTR_FORMAT" in region "
+                                 "["PTR_FORMAT", "PTR_FORMAT")",
+                                 p, (void*) _containing_obj,
+                                 from->bottom(), from->end());
+          print_object(gclog_or_tty, _containing_obj);
+          gclog_or_tty->print_cr("points to obj "PTR_FORMAT" not in the heap",
+                                 (void*) obj);
         } else {
+          HeapRegion* from = _g1h->heap_region_containing((HeapWord*)p);
+          HeapRegion* to   = _g1h->heap_region_containing((HeapWord*)obj);
           gclog_or_tty->print_cr("Field "PTR_FORMAT
-                        " of live obj "PTR_FORMAT
-                        " points to dead obj "PTR_FORMAT".",
-                        p, (void*) _containing_obj, (void*) obj);
+                                 " of live obj "PTR_FORMAT" in region "
+                                 "["PTR_FORMAT", "PTR_FORMAT")",
+                                 p, (void*) _containing_obj,
+                                 from->bottom(), from->end());
+          print_object(gclog_or_tty, _containing_obj);
+          gclog_or_tty->print_cr("points to dead obj "PTR_FORMAT" in region "
+                                 "["PTR_FORMAT", "PTR_FORMAT")",
+                                 (void*) obj, to->bottom(), to->end());
+          print_object(gclog_or_tty, obj);
         }
-        gclog_or_tty->print_cr("Live obj:");
-        _containing_obj->print_on(gclog_or_tty);
-        gclog_or_tty->print_cr("Bad referent:");
-        obj->print_on(gclog_or_tty);
         gclog_or_tty->print_cr("----------");
         _failures = true;
         failed = true;
@@ -723,6 +741,8 @@ void HeapRegion::print_on(outputStream* st) const {
   else
     st->print("  ");
   st->print(" %5d", _gc_time_stamp);
+  st->print(" PTAMS "PTR_FORMAT" NTAMS "PTR_FORMAT,
+            prev_top_at_mark_start(), next_top_at_mark_start());
   G1OffsetTableContigSpace::print_on(st);
 }