8200450: Root cause analysis for JDK-8200366
authorlucy
Wed, 18 Apr 2018 21:10:09 -0700
changeset 49825 f909f09569ca
parent 49824 e242740a92b8
child 49826 ad1a5f49b8ae
8200450: Root cause analysis for JDK-8200366 Summary: add safeguard checks to make sure CodeBlob if fully initialized Reviewed-by: kvn
src/hotspot/share/code/codeHeapState.cpp
src/hotspot/share/code/codeHeapState.hpp
src/hotspot/share/services/diagnosticCommand.cpp
--- a/src/hotspot/share/code/codeHeapState.cpp	Wed Apr 18 18:43:04 2018 -0400
+++ b/src/hotspot/share/code/codeHeapState.cpp	Wed Apr 18 21:10:09 2018 -0700
@@ -613,16 +613,22 @@
       //---<  some sanity checks  >---
       // Do not assert here, just check, print error message and return.
       // This is a diagnostic function. It is not supposed to tear down the VM.
-      if ((char*)h <  low_bound ) {
+      if ((char*)h <  low_bound) {
         insane = true; ast->print_cr("Sanity check: HeapBlock @%p below low bound (%p)", (char*)h, low_bound);
       }
-      if (ix_end   >= granules  ) {
+      if ((char*)h >  (low_bound + res_size)) {
+        insane = true; ast->print_cr("Sanity check: HeapBlock @%p outside reserved range (%p)", (char*)h, low_bound + res_size);
+      }
+      if ((char*)h >  (low_bound + size)) {
+        insane = true; ast->print_cr("Sanity check: HeapBlock @%p outside used range (%p)", (char*)h, low_bound + size);
+      }
+      if (ix_end   >= granules) {
         insane = true; ast->print_cr("Sanity check: end index (%d) out of bounds (" SIZE_FORMAT ")", ix_end, granules);
       }
       if (size     != heap->capacity()) {
         insane = true; ast->print_cr("Sanity check: code heap capacity has changed (" SIZE_FORMAT "K to " SIZE_FORMAT "K)", size/(size_t)K, heap->capacity()/(size_t)K);
       }
-      if (ix_beg   >  ix_end    ) {
+      if (ix_beg   >  ix_end) {
         insane = true; ast->print_cr("Sanity check: end index (%d) lower than begin index (%d)", ix_end, ix_beg);
       }
       if (insane) {
@@ -988,6 +994,11 @@
       ast->print_cr("  deadSpace      = " SIZE_FORMAT_W(8) "k, nBlocks_dead     = %6d, %10.3f%% of capacity, %10.3f%% of max_capacity", deadSpace/(size_t)K,     nBlocks_dead,     (100.0*deadSpace)/size,     (100.0*deadSpace)/res_size);
       ast->print_cr("  stubSpace      = " SIZE_FORMAT_W(8) "k, nBlocks_stub     = %6d, %10.3f%% of capacity, %10.3f%% of max_capacity", stubSpace/(size_t)K,     nBlocks_stub,     (100.0*stubSpace)/size,     (100.0*stubSpace)/res_size);
       ast->print_cr("ZombieBlocks     = %8d. These are HeapBlocks which could not be identified as CodeBlobs.", nBlocks_zomb);
+      ast->cr();
+      ast->print_cr("Segment start          = " INTPTR_FORMAT ", used space      = " SIZE_FORMAT_W(8)"k", p2i(low_bound), size/K);
+      ast->print_cr("Segment end (used)     = " INTPTR_FORMAT ", remaining space = " SIZE_FORMAT_W(8)"k", p2i(low_bound) + size, (res_size - size)/K);
+      ast->print_cr("Segment end (reserved) = " INTPTR_FORMAT ", reserved space  = " SIZE_FORMAT_W(8)"k", p2i(low_bound) + res_size, res_size/K);
+      ast->cr();
       ast->print_cr("latest allocated compilation id = %d", latest_compilation_id);
       ast->print_cr("highest observed compilation id = %d", highest_compilation_id);
       ast->print_cr("Building TopSizeList iterations = %ld", total_iterations);
@@ -1218,14 +1229,14 @@
           blob_name = this_blob->name();
           nm        = this_blob->as_nmethod_or_null();
           //---<  blob address  >---
-          ast->print("%p", this_blob);
+          ast->print(INTPTR_FORMAT, p2i(this_blob));
           ast->fill_to(19);
           //---<  blob offset from CodeHeap begin  >---
           ast->print("(+" PTR32_FORMAT ")", (unsigned int)((char*)this_blob-low_bound));
           ast->fill_to(33);
         } else {
           //---<  block address  >---
-          ast->print("%p", TopSizeArray[i].start);
+          ast->print(INTPTR_FORMAT, p2i(TopSizeArray[i].start));
           ast->fill_to(19);
           //---<  block offset from CodeHeap begin  >---
           ast->print("(+" PTR32_FORMAT ")", (unsigned int)((char*)TopSizeArray[i].start-low_bound));
@@ -1404,7 +1415,7 @@
 
     unsigned int ix = 0;
     for (ix = 0; ix < alloc_freeBlocks-1; ix++) {
-      ast->print("%p: Len[%4d] = " HEX32_FORMAT ",", FreeArray[ix].start, ix, FreeArray[ix].len);
+      ast->print(INTPTR_FORMAT ": Len[%4d] = " HEX32_FORMAT ",", p2i(FreeArray[ix].start), ix, FreeArray[ix].len);
       ast->fill_to(38);
       ast->print("Gap[%4d..%4d]: " HEX32_FORMAT " bytes,", ix, ix+1, FreeArray[ix].gap);
       ast->fill_to(71);
@@ -1414,7 +1425,7 @@
       }
       STRINGSTREAM_FLUSH_LOCKED("\n")
     }
-    ast->print_cr("%p: Len[%4d] = " HEX32_FORMAT, FreeArray[ix].start, ix, FreeArray[ix].len);
+    ast->print_cr(INTPTR_FORMAT ": Len[%4d] = " HEX32_FORMAT, p2i(FreeArray[ix].start), ix, FreeArray[ix].len);
     STRINGSTREAM_FLUSH_LOCKED("\n\n")
   }
 
@@ -2039,10 +2050,16 @@
 }
 
 
+#define JDK8200450_REMEDY
+#define JDK8200450_TRACE
 void CodeHeapState::print_names(outputStream* out, CodeHeap* heap) {
   if (!initialization_complete) {
     return;
   }
+#ifdef JDK8200450_TRACE
+  out->print_cr("print_names() entered for heap @ " INTPTR_FORMAT, p2i(heap));
+  out->flush();
+#endif
 
   const char* heapName   = get_heapName(heap);
   get_HeapStatGlobals(out, heapName);
@@ -2057,7 +2074,7 @@
   CodeBlob*    last_blob          = NULL;
   bool         name_in_addr_range = true;
 
-  //---<  print at least 128K per block  >---
+  //---<  print at least 128K per block (i.e. between headers)  >---
   if (granules_per_line*granule_size < 128*K) {
     granules_per_line = (unsigned int)((128*K)/granule_size);
   }
@@ -2067,7 +2084,7 @@
                 "  Due to the living nature of the code heap and because the CodeCache_lock\n"
                 "  is not continuously held, the displayed name might be wrong or no name\n"
                 "  might be found at all. The likelihood for that to happen increases\n"
-                "  over time passed between analysis and print step.\n");
+                "  over time passed between aggregtion and print steps.\n");
   STRINGSTREAM_FLUSH_LOCKED("")
 
   for (unsigned int ix = 0; ix < alloc_granules; ix++) {
@@ -2078,23 +2095,69 @@
       }
       name_in_addr_range = false;
 
+      size_t end_ix = (ix+granules_per_line <= alloc_granules) ? ix+granules_per_line : alloc_granules;
       ast->cr();
       ast->print_cr("--------------------------------------------------------------------");
-      ast->print_cr("Address range [%p,%p), " SIZE_FORMAT "k", low_bound+ix*granule_size, low_bound+(ix+granules_per_line)*granule_size, granules_per_line*granule_size/(size_t)K);
+      ast->print_cr("Address range [" INTPTR_FORMAT "," INTPTR_FORMAT "), " SIZE_FORMAT "k", p2i(low_bound+ix*granule_size), p2i(low_bound + end_ix*granule_size), (end_ix - ix)*granule_size/(size_t)K);
       ast->print_cr("--------------------------------------------------------------------");
       STRINGSTREAM_FLUSH_LOCKED("")
     }
     // Only check granule if it contains at least one blob.
     unsigned int nBlobs  = StatArray[ix].t1_count   + StatArray[ix].t2_count + StatArray[ix].tx_count +
                            StatArray[ix].stub_count + StatArray[ix].dead_count;
-    if (nBlobs > 0 ) {
+#ifdef JDK8200450_REMEDY
+    if (nBlobs > 0 )
+#endif
+    {
     for (unsigned int is = 0; is < granule_size; is+=(unsigned int)seg_size) {
       // heap->find_start() is safe. Only working with _segmap. Returns NULL or void*. Returned CodeBlob may be uninitialized.
       CodeBlob* this_blob = (CodeBlob *)(heap->find_start(low_bound+ix*granule_size+is));
-      bool blob_initialized = (this_blob != NULL) &&
-                              ((char*)this_blob + this_blob->header_size() == (char*)(this_blob->relocation_begin())) &&
-                              ((char*)this_blob + CodeBlob::align_code_offset(this_blob->header_size() + this_blob->relocation_size()) == (char*)(this_blob->content_begin()));
+#ifndef JDK8200450_REMEDY
+      bool blob_initialized = (this_blob != NULL)
+#else
+#ifndef JDK8200450_TRACE
+      bool blob_initialized = (this_blob != NULL) && (this_blob->header_size() >= 0) && (this_blob->relocation_size() >= 0) &&
+                              ((address)this_blob + this_blob->header_size() == (address)(this_blob->relocation_begin())) &&
+                              ((address)this_blob + CodeBlob::align_code_offset(this_blob->header_size() + this_blob->relocation_size()) == (address)(this_blob->content_begin()) &&
+                              is_readable_pointer((address)(this_blob->relocation_begin()) &&
+                              is_readable_pointer(this_blob->content_begin());
+#else
+      int   hdr_size      = 0;
+      int   reloc_size    = 0;
+      address reloc_begin = NULL;
+      address cntnt_begin = NULL;
+      if (this_blob != NULL) {
+        hdr_size    = this_blob->header_size();
+        reloc_size  = this_blob->relocation_size();
+        reloc_begin = (address)(this_blob->relocation_begin());
+        cntnt_begin = this_blob->content_begin();
+      }
+      bool blob_initialized = (this_blob != NULL) && (hdr_size >= 0) && (reloc_size >= 0) &&
+                              ((address)this_blob + hdr_size == reloc_begin) &&
+                              ((address)this_blob + CodeBlob::align_code_offset(hdr_size + reloc_size) == cntnt_begin) &&
+                              is_readable_pointer(reloc_begin) &&
+                              is_readable_pointer(cntnt_begin);
+#endif
+#endif
       if (blob_initialized && (this_blob != last_blob)) {
+        last_blob          = this_blob;
+
+        //---<  get type and name  >---
+        blobType       cbType = noType;
+        if (segment_granules) {
+          cbType = (blobType)StatArray[ix].type;
+        } else {
+          cbType = get_cbType(this_blob);  // Is this here safe?
+        }
+        // this_blob->name() could return NULL if no name is given to CTOR. Inlined, maybe invisible on stack
+        const char* blob_name = this_blob->name();
+#ifdef JDK8200450_REMEDY
+        if (blob_name == NULL) {
+          blob_name = "<unavailable>";
+        }
+#endif
+
+        //---<  print table header for new print range  >---
         if (!name_in_addr_range) {
           name_in_addr_range = true;
           ast->fill_to(51);
@@ -2102,32 +2165,34 @@
           ast->fill_to(61);
           ast->print_cr("%6s", "method");
           ast->print_cr("%18s %13s %17s %9s  %5s %18s  %s", "Addr(module)      ", "offset", "size", " type lvl", " temp", "blobType          ", "Name");
+          STRINGSTREAM_FLUSH_LOCKED("")
         }
 
-        //---<  Print blobTypeName as recorded during analysis  >---
-        ast->print("%p", this_blob);
+        //---<  print line prefix (address and offset from CodeHeap start)  >---
+        ast->print(INTPTR_FORMAT, p2i(this_blob));
         ast->fill_to(19);
         ast->print("(+" PTR32_FORMAT ")", (unsigned int)((char*)this_blob-low_bound));
         ast->fill_to(33);
 
-        //---<  print size, name, and signature (for nMethods)  >---
-        // this_blob->name() could return NULL if no name is given to CTOR. Inlined, maybe not visible on stack
-        const char* blob_name = this_blob->name();
-        if (blob_name == 0) {
-          blob_name = "<unavailable>";
-        }
-        // this_blob->as_nmethod_or_null() is safe. Inlined, maybe not visible on stack.
-        nmethod*           nm = this_blob->as_nmethod_or_null();
-        blobType       cbType = noType;
-        if (segment_granules) {
-          cbType = (blobType)StatArray[ix].type;
-        } else {
-          cbType = get_cbType(this_blob);
-        }
-        if ((nm != NULL) && (nm->method() != NULL)) {
+#ifdef JDK8200450_TRACE
+        STRINGSTREAM_FLUSH_LOCKED("")   // Remove before push!!!
+#endif
+
+        // this_blob->as_nmethod_or_null() is safe. Inlined, maybe invisible on stack.
+        nmethod*    nm     = this_blob->as_nmethod_or_null();
+        Method*     method = (nm == NULL) ? NULL : nm->method();  // may be uninitialized, i.e. != NULL, but invalid
+#ifdef JDK8200450_REMEDY
+        if ((nm != NULL) && (method != NULL) && is_readable_pointer(method) && is_readable_pointer(method->constants())) {
+#else
+        if ((nm != NULL) && (method != NULL)) {
+#endif
           ResourceMark rm;
+          //---<  collect all data to locals as quickly as possible  >---
+          unsigned int total_size = nm->total_size();
+          int          hotness    = nm->hotness_counter();
+          bool         nm_zombie  = nm->is_zombie();
+          bool         get_name   = nm->is_in_use() || nm->is_not_entrant();
           //---<  nMethod size in hex  >---
-          unsigned int total_size = nm->total_size();
           ast->print(PTR32_FORMAT, total_size);
           ast->print("(" SIZE_FORMAT_W(4) "K)", total_size/K);
           //---<  compiler information  >---
@@ -2135,21 +2200,36 @@
           ast->print("%5s %3d", compTypeName[StatArray[ix].compiler], StatArray[ix].level);
           //---<  method temperature  >---
           ast->fill_to(62);
-          ast->print("%5d", nm->hotness_counter());
+          ast->print("%5d", hotness);
           //---<  name and signature  >---
           ast->fill_to(62+6);
           ast->print("%s", blobTypeName[cbType]);
           ast->fill_to(82+6);
-          if (nm->is_in_use()) {
-            blob_name = nm->method()->name_and_sig_as_C_string();
-          }
-          if (nm->is_not_entrant()) {
-            blob_name = nm->method()->name_and_sig_as_C_string();
-          }
-          if (nm->is_zombie()) {
+          if (nm_zombie) {
             ast->print("%14s", " zombie method");
           }
-          ast->print("%s", blob_name);
+
+#ifdef JDK8200450_TRACE
+        STRINGSTREAM_FLUSH_LOCKED("")   // Remove before push!!!
+#endif
+
+          if (get_name) {
+#ifdef JDK8200450_REMEDY
+            Symbol* methName  = method->name();
+            const char*   methNameS = (methName == NULL) ? NULL : methName->as_C_string();
+            methNameS = (methNameS == NULL) ? "<method name unavailable>" : methNameS;
+            Symbol* methSig   = method->signature();
+            const char*   methSigS  = (methSig  == NULL) ? NULL : methSig->as_C_string();
+            methSigS  = (methSigS  == NULL) ? "<method signature unavailable>" : methSigS;
+            ast->print("%s", methNameS);
+            ast->print("%s", methSigS);
+#else
+            blob_name = method->name_and_sig_as_C_string();
+            ast->print("%s", blob_name);
+#endif
+          } else {
+            ast->print("%s", blob_name);
+          }
         } else {
           ast->fill_to(62+6);
           ast->print("%s", blobTypeName[cbType]);
@@ -2157,12 +2237,48 @@
           ast->print("%s", blob_name);
         }
         STRINGSTREAM_FLUSH_LOCKED("\n")
+#ifdef JDK8200450_TRACE
+        if ((nm != NULL) && (method != NULL) && !(is_readable_pointer(method) && is_readable_pointer(method->constants()))) {
+          ast->print("Potential CodeHeap State Analytics issue found.\n");
+          if (is_readable_pointer(method)) {
+            ast->print("  Issue would have been detected by is_readable_pointer(" INTPTR_FORMAT "(method->constants())) check.\n", p2i(method->constants()));
+          } else {
+            ast->print("  Issue would have been detected by is_readable_pointer(" INTPTR_FORMAT "(method)) check.\n", p2i(method));
+          }
+          STRINGSTREAM_FLUSH_LOCKED("\n")
+        }
+#endif
+      } else if (!blob_initialized && (this_blob != last_blob) && (this_blob != NULL)) {
         last_blob          = this_blob;
-      } else if (!blob_initialized && (this_blob != NULL)) {
-        last_blob          = this_blob;
+#ifdef JDK8200450_TRACE
+        ast->print("Potential CodeHeap State Analytics issue found.\n");
+        if (nBlobs == 0) {
+          ast->print("  Issue would have been detected by (nBlobs > 0) check.\n");
+        } else {
+          if (!((address)this_blob + hdr_size == reloc_begin)) {
+            ast->print("  Issue would have been detected by (this(" INTPTR_FORMAT ") + header(%d) == relocation_begin(" INTPTR_FORMAT ")) check.\n", p2i(this_blob), hdr_size, p2i(reloc_begin));
+          }
+          if (!((address)this_blob + CodeBlob::align_code_offset(hdr_size + reloc_size) == cntnt_begin)) {
+            ast->print("  Issue would have been detected by (this(" INTPTR_FORMAT ") + header(%d) + relocation(%d) == content_begin(" INTPTR_FORMAT ")) check.\n", p2i(this_blob), hdr_size, reloc_size, p2i(cntnt_begin));
+          }
+          if (hdr_size    != this_blob->header_size()) {
+            ast->print("  header_size      meanwhile changed from %d to %d\n", hdr_size, this_blob->header_size());
+          }
+          if (reloc_size  != this_blob->relocation_size()) {
+            ast->print("  relocation_size  meanwhile changed from %d to %d\n", reloc_size, this_blob->relocation_size());
+          }
+          if (reloc_begin != (address)(this_blob->relocation_begin())) {
+            ast->print("  relocation_begin meanwhile changed from " INTPTR_FORMAT " to " INTPTR_FORMAT "\n", p2i(reloc_begin), p2i(this_blob->relocation_begin()));
+          }
+          if (cntnt_begin != this_blob->content_begin()) {
+            ast->print("  relocation_begin meanwhile changed from " INTPTR_FORMAT " to " INTPTR_FORMAT "\n", p2i(cntnt_begin), p2i(this_blob->content_begin()));
+          }
+        }
+        STRINGSTREAM_FLUSH_LOCKED("\n")
+#endif
       }
     }
-    }
+    } // nBlobs > 0
   }
   STRINGSTREAM_FLUSH_LOCKED("\n\n")
 }
@@ -2287,7 +2403,7 @@
     ast->cr();
     assert(out == ast, "must use the same stream!");
 
-    ast->print("%p", low_bound + ix*granule_size);
+    ast->print(INTPTR_FORMAT, p2i(low_bound + ix*granule_size));
     ast->fill_to(19);
     ast->print("(+" PTR32_FORMAT "): |", (unsigned int)(ix*granule_size));
   }
@@ -2307,7 +2423,7 @@
       ast->reset();
     }
 
-    ast->print("%p", low_bound + ix*granule_size);
+    ast->print(INTPTR_FORMAT, p2i(low_bound + ix*granule_size));
     ast->fill_to(19);
     ast->print("(+" PTR32_FORMAT "): |", (unsigned int)(ix*granule_size));
   }
@@ -2336,3 +2452,17 @@
   }
   return noType;
 }
+
+// Check if pointer can be read from (4-byte read access).
+// Helps to prove validity of a not-NULL pointer.
+// Returns true in very early stages of VM life when stub is not yet generated.
+#define SAFEFETCH_DEFAULT true
+bool CodeHeapState::is_readable_pointer(const void* p) {
+  if (!CanUseSafeFetch32()) {
+    return SAFEFETCH_DEFAULT;
+  }
+  int* const aligned = (int*) align_down((intptr_t)p, 4);
+  int cafebabe = 0xcafebabe;  // tester value 1
+  int deadbeef = 0xdeadbeef;  // tester value 2
+  return (SafeFetch32(aligned, cafebabe) != cafebabe) || (SafeFetch32(aligned, deadbeef) != deadbeef);
+}
--- a/src/hotspot/share/code/codeHeapState.hpp	Wed Apr 18 18:43:04 2018 -0400
+++ b/src/hotspot/share/code/codeHeapState.hpp	Wed Apr 18 21:10:09 2018 -0700
@@ -93,6 +93,7 @@
   static void print_line_delim(outputStream* out, bufferedStream *sst, char* low_bound, unsigned int ix, unsigned int gpl);
   static void print_line_delim(outputStream* out, outputStream *sst, char* low_bound, unsigned int ix, unsigned int gpl);
   static blobType get_cbType(CodeBlob* cb);
+  static bool is_readable_pointer(const void* p);
 
  public:
   static void discard(outputStream* out, CodeHeap* heap);
--- a/src/hotspot/share/services/diagnosticCommand.cpp	Wed Apr 18 18:43:04 2018 -0400
+++ b/src/hotspot/share/services/diagnosticCommand.cpp	Wed Apr 18 21:10:09 2018 -0700
@@ -931,7 +931,7 @@
 //---<  BEGIN  >--- CodeHeap State Analytics.
 CodeHeapAnalyticsDCmd::CodeHeapAnalyticsDCmd(outputStream* output, bool heap) :
                                              DCmdWithParser(output, heap),
-  _function("function", "Function to be performed (aggregate, UsedSpace, FreeSpace, MethodCount, MethodSpace, MethodAge, discard", "STRING", false, "all"),
+  _function("function", "Function to be performed (aggregate, UsedSpace, FreeSpace, MethodCount, MethodSpace, MethodAge, MethodNames, discard", "STRING", false, "all"),
   _granularity("granularity", "Detail level - smaller value -> more detail", "STRING", false, "4096") {
   _dcmdparser.add_dcmd_argument(&_function);
   _dcmdparser.add_dcmd_argument(&_granularity);