8255973: Add more logging to debug JDK-8255917

Reviewed-by: ccheung, stuefe, iklam

Author: yminqi

src/hotspot/share/logging/logTag.hpp

@@ -118,6 +118,7 @@
   LOG_TAG(monitormismatch) \
   LOG_TAG(nestmates) \
   LOG_TAG(nmethod) \
+  LOG_TAG(nmt) \
   LOG_TAG(normalize) \
   LOG_TAG(numa) \
   LOG_TAG(objecttagging) \

src/hotspot/share/runtime/os.cpp

@@ -1668,6 +1668,9 @@ char* os::attempt_reserve_memory_at(char* addr, size_t bytes) {
   char* result = pd_attempt_reserve_memory_at(addr, bytes);
   if (result != NULL) {
     MemTracker::record_virtual_memory_reserve((address)result, bytes, CALLER_PC);
+  } else {
+    log_debug(os)("Attempt to reserve memory at " INTPTR_FORMAT " for "
+                 SIZE_FORMAT " bytes failed, errno %d", p2i(addr), bytes, get_last_error());
   }
   return result;
 }

src/hotspot/share/services/virtualMemoryTracker.cpp

@@ -290,7 +290,7 @@ size_t ReservedMemoryRegion::committed_size() const {
 
 void ReservedMemoryRegion::set_flag(MEMFLAGS f) {
   assert((flag() == mtNone || flag() == f),
-         "Overwrite memory type for region [" PTR_FORMAT "-" PTR_FORMAT "), %u->%u.",
+         "Overwrite memory type for region [" INTPTR_FORMAT "-" INTPTR_FORMAT "), %u->%u.",
          p2i(base()), p2i(end()), (unsigned)flag(), (unsigned)f);
   if (flag() != f) {
     VirtualMemorySummary::move_reserved_memory(flag(), f, size());
@@ -343,6 +343,8 @@ bool VirtualMemoryTracker::add_reserved_region(address base_addr, size_t size,
   ReservedMemoryRegion  rgn(base_addr, size, stack, flag);
   ReservedMemoryRegion* reserved_rgn = _reserved_regions->find(rgn);
 
+  log_debug(nmt)("Add reserved region \'%s\' (" INTPTR_FORMAT ", " SIZE_FORMAT ")",
+                rgn.flag_name(), p2i(rgn.base()), rgn.size());
   if (reserved_rgn == NULL) {
     VirtualMemorySummary::record_reserved_memory(size, flag);
     return _reserved_regions->add(rgn) != NULL;
@@ -381,21 +383,25 @@ bool VirtualMemoryTracker::add_reserved_region(address base_addr, size_t size,
       // CDS reserves the whole region for mapping CDS archive, then maps each section into the region.
       // NMT reports CDS as a whole.
       if (reserved_rgn->flag() == mtClassShared) {
+        log_debug(nmt)("CDS reserved region \'%s\' as a whole (" INTPTR_FORMAT ", " SIZE_FORMAT ")",
+                      reserved_rgn->flag_name(), p2i(reserved_rgn->base()), reserved_rgn->size());
         assert(reserved_rgn->contain_region(base_addr, size), "Reserved CDS region should contain this mapping region");
         return true;
       }
 
       // Mapped CDS string region.
       // The string region(s) is part of the java heap.
       if (reserved_rgn->flag() == mtJavaHeap) {
+        log_debug(nmt)("CDS reserved region \'%s\' as a whole (" INTPTR_FORMAT ", " SIZE_FORMAT ")",
+                      reserved_rgn->flag_name(), p2i(reserved_rgn->base()), reserved_rgn->size());
         assert(reserved_rgn->contain_region(base_addr, size), "Reserved heap region should contain this mapping region");
         return true;
       }
 
       // Print some more details. Don't use UL here to avoid circularities.
 #ifdef ASSERT
-      tty->print_cr("Error: existing region: [" PTR_FORMAT "-" PTR_FORMAT "), flag %u.\n"
-                    "       new region: [" PTR_FORMAT "-" PTR_FORMAT "), flag %u.",
+      tty->print_cr("Error: existing region: [" INTPTR_FORMAT "-" INTPTR_FORMAT "), flag %u.\n"
+                    "       new region: [" INTPTR_FORMAT "-" INTPTR_FORMAT "), flag %u.",
                     p2i(reserved_rgn->base()), p2i(reserved_rgn->end()), (unsigned)reserved_rgn->flag(),
                     p2i(base_addr), p2i(base_addr + size), (unsigned)flag);
 #endif
@@ -430,9 +436,15 @@ bool VirtualMemoryTracker::add_committed_region(address addr, size_t size,
   ReservedMemoryRegion  rgn(addr, size);
   ReservedMemoryRegion* reserved_rgn = _reserved_regions->find(rgn);
 
-  assert(reserved_rgn != NULL, "No reserved region");
+  if (reserved_rgn == NULL) {
+    log_debug(nmt)("Add committed region \'%s\', No reserved region found for  (" INTPTR_FORMAT ", " SIZE_FORMAT ")",
+                  rgn.flag_name(),  p2i(rgn.base()), rgn.size());
+  }
+  assert(reserved_rgn != NULL, "Add committed region, No reserved region found");
   assert(reserved_rgn->contain_region(addr, size), "Not completely contained");
   bool result = reserved_rgn->add_committed_region(addr, size, stack);
+  log_debug(nmt)("Add committed region \'%s\'(" INTPTR_FORMAT ", " SIZE_FORMAT ") %s",
+                rgn.flag_name(),  p2i(rgn.base()), rgn.size(), (result ? "Succeeded" : "Failed"));
   return result;
 }
 
@@ -443,9 +455,12 @@ bool VirtualMemoryTracker::remove_uncommitted_region(address addr, size_t size)
 
   ReservedMemoryRegion  rgn(addr, size);
   ReservedMemoryRegion* reserved_rgn = _reserved_regions->find(rgn);
-  assert(reserved_rgn != NULL, "No reserved region");
+  assert(reserved_rgn != NULL, "No reserved region (" INTPTR_FORMAT ", " SIZE_FORMAT ")", p2i(addr), size);
   assert(reserved_rgn->contain_region(addr, size), "Not completely contained");
+  const char* flag_name = reserved_rgn->flag_name();  // after remove, info is not complete
   bool result = reserved_rgn->remove_uncommitted_region(addr, size);
+  log_debug(nmt)("Removed uncommitted region \'%s\' (" INTPTR_FORMAT ", " SIZE_FORMAT ") %s",
+                flag_name,  p2i(addr), size, (result ? " Succeeded" : "Failed"));
   return result;
 }
 
@@ -454,12 +469,19 @@ bool VirtualMemoryTracker::remove_released_region(ReservedMemoryRegion* rgn) {
   assert(_reserved_regions != NULL, "Sanity check");
 
   // uncommit regions within the released region
-  if (!rgn->remove_uncommitted_region(rgn->base(), rgn->size())) {
+  ReservedMemoryRegion backup(*rgn);
+  bool result = rgn->remove_uncommitted_region(rgn->base(), rgn->size());
+  log_debug(nmt)("Remove uncommitted region \'%s\' (" INTPTR_FORMAT ", " SIZE_FORMAT ") %s",
+                backup.flag_name(), p2i(backup.base()), backup.size(), (result ? "Succeeded" : "Failed"));
+  if (!result) {
     return false;
   }
 
   VirtualMemorySummary::record_released_memory(rgn->size(), rgn->flag());
-  return _reserved_regions->remove(*rgn);
+  result =  _reserved_regions->remove(*rgn);
+  log_debug(nmt)("Removed region \'%s\' (" INTPTR_FORMAT ", " SIZE_FORMAT ") from _resvered_regions %s" ,
+                backup.flag_name(), p2i(backup.base()), backup.size(), (result ? "Succeeded" : "Failed"));
+  return result;
 }
 
 bool VirtualMemoryTracker::remove_released_region(address addr, size_t size) {
@@ -470,6 +492,10 @@ bool VirtualMemoryTracker::remove_released_region(address addr, size_t size) {
   ReservedMemoryRegion  rgn(addr, size);
   ReservedMemoryRegion* reserved_rgn = _reserved_regions->find(rgn);
 
+  if (reserved_rgn == NULL) {
+    log_debug(nmt)("No reserved region found for (" INTPTR_FORMAT ", " SIZE_FORMAT ")!",
+                  p2i(rgn.base()), rgn.size());
+  }
   assert(reserved_rgn != NULL, "No reserved region");
   if (reserved_rgn->same_region(addr, size)) {
     return remove_released_region(reserved_rgn);
@@ -527,8 +553,10 @@ bool VirtualMemoryTracker::split_reserved_region(address addr, size_t size, size
   NativeCallStack original_stack = *reserved_rgn->call_stack();
   MEMFLAGS original_flags = reserved_rgn->flag();
 
+  const char* name = reserved_rgn->flag_name();
   remove_released_region(reserved_rgn);
-
+  log_debug(nmt)("Split region \'%s\' (" INTPTR_FORMAT ", " SIZE_FORMAT ")  with size " SIZE_FORMAT,
+                name, p2i(rgn.base()), rgn.size(), split);
   // Now, create two new regions.
   add_reserved_region(addr, split, original_stack, original_flags);
   add_reserved_region(addr + split, size - split, original_stack, original_flags);

src/hotspot/share/services/virtualMemoryTracker.hpp

@@ -340,6 +340,8 @@ class ReservedMemoryRegion : public VirtualMemoryRegion {
     return *this;
   }
 
+  const char* flag_name() { return NMTUtil::flag_to_name(_flag); }
+
  private:
   // The committed region contains the uncommitted region, subtract the uncommitted
   // region from this committed region

test/hotspot/jtreg/runtime/cds/SharedBaseAddress.java

@@ -60,6 +60,8 @@ public static void main(String[] args) throws Exception {
                 .addPrefix("-XX:SharedBaseAddress=" + testEntry)
                 .addPrefix("-Xlog:cds=debug")
                 .addPrefix("-Xlog:cds+reloc=debug")
+                .addPrefix("-Xlog:nmt=debug")
+                .addPrefix("-Xlog:os=debug")
                 .addPrefix("-XX:NativeMemoryTracking=detail");
 
             CDSTestUtils.createArchiveAndCheck(opts);