8272586: emit abstract machine code in hs-err logs

Reviewed-by: kvn, dholmes

src/hotspot/share/code/nmethod.cpp

@@ -67,6 +67,7 @@
 #include "runtime/sharedRuntime.hpp"
 #include "runtime/signature.hpp"
 #include "runtime/sweeper.hpp"
+#include "runtime/threadWXSetters.inline.hpp"
 #include "runtime/vmThread.hpp"
 #include "utilities/align.hpp"
 #include "utilities/copy.hpp"
@@ -923,7 +924,7 @@ void nmethod::print_on(outputStream* st, const char* msg) const {
       CompileTask::print(st, this, msg, /*short_form:*/ true);
       st->print_cr(" (" INTPTR_FORMAT ")", p2i(this));
     } else {
-      CompileTask::print(st, this, msg, /*short_form:*/ false);
+      CompileTask::print(st, this, msg, /*short_form:*/ false, /* cr */ true, /* timestamp */ false);
     }
   }
 }
@@ -2528,7 +2529,7 @@ void nmethod::print(outputStream* st) const {
     st->print("(n/a) ");
   }
 
-  print_on(tty, NULL);
+  print_on(st, NULL);
 
   if (WizardMode) {
     st->print("((nmethod*) " INTPTR_FORMAT ") ", p2i(this));
@@ -2879,6 +2880,9 @@ void nmethod::decode2(outputStream* ost) const {
                                                                   AbstractDisassembler::show_block_comment());
 #endif
 
+  // Decoding an nmethod can write to a PcDescCache (see PcDescCache::add_pc_desc)
+  MACOS_AARCH64_ONLY(ThreadWXEnable wx(WXWrite, Thread::current());)
+
   st->cr();
   this->print(st);
   st->cr();

src/hotspot/share/compiler/compileTask.cpp

@@ -236,11 +236,13 @@ void CompileTask::print_tty() {
 // CompileTask::print_impl
 void CompileTask::print_impl(outputStream* st, Method* method, int compile_id, int comp_level,
                              bool is_osr_method, int osr_bci, bool is_blocking,
-                             const char* msg, bool short_form, bool cr,
+                             const char* msg, bool short_form, bool cr, bool timestamp,
                              jlong time_queued, jlong time_started) {
   if (!short_form) {
+    if (timestamp) {
       // Print current time
       st->print("%7d ", (int)tty->time_stamp().milliseconds());
+    }
     if (Verbose && time_queued != 0) {
       // Print time in queue and time being processed by compiler thread
       jlong now = os::elapsed_counter();

src/hotspot/share/compiler/compileTask.hpp

@@ -187,16 +187,16 @@ class CompileTask : public CHeapObj<mtCompiler> {
 private:
   static void  print_impl(outputStream* st, Method* method, int compile_id, int comp_level,
                                       bool is_osr_method = false, int osr_bci = -1, bool is_blocking = false,
-                                      const char* msg = NULL, bool short_form = false, bool cr = true,
+                                      const char* msg = NULL, bool short_form = false, bool cr = true, bool timestamp = true,
                                       jlong time_queued = 0, jlong time_started = 0);
 
 public:
   void         print(outputStream* st = tty, const char* msg = NULL, bool short_form = false, bool cr = true);
   void         print_ul(const char* msg = NULL);
-  static void  print(outputStream* st, const nmethod* nm, const char* msg = NULL, bool short_form = false, bool cr = true) {
+  static void  print(outputStream* st, const nmethod* nm, const char* msg = NULL, bool short_form = false, bool cr = true, bool timestamp = true) {
     print_impl(st, nm->method(), nm->compile_id(), nm->comp_level(),
                            nm->is_osr_method(), nm->is_osr_method() ? nm->osr_entry_bci() : -1, /*is_blocking*/ false,
-                           msg, short_form, cr);
+                           msg, short_form, cr, timestamp);
   }
   static void  print_ul(const nmethod* nm, const char* msg = NULL);
 

src/hotspot/share/compiler/disassembler.cpp

@@ -872,7 +872,7 @@ void Disassembler::decode(CodeBlob* cb, outputStream* st) {
   if (cb->is_nmethod()) {
     // If we  have an nmethod at hand,
     // call the specialized decoder directly.
-    decode((nmethod*)cb, st);
+    ((nmethod*)cb)->decode2(st);
     return;
   }
 

src/hotspot/share/utilities/vmError.cpp

@@ -87,6 +87,7 @@ Thread*           VMError::_thread;
 address           VMError::_pc;
 void*             VMError::_siginfo;
 void*             VMError::_context;
+bool              VMError::_print_native_stack_used = false;
 const char*       VMError::_filename;
 int               VMError::_lineno;
 size_t            VMError::_size;
@@ -241,6 +242,107 @@ void VMError::print_stack_trace(outputStream* st, JavaThread* jt,
 #endif // ZERO
 }
 
+/**
+ * Adds `value` to `list` iff it's not already present and there is sufficient
+ * capacity (i.e. length(list) < `list_capacity`). The length of the list
+ * is the index of the first nullptr entry.
+ *
+ * @ return true if the value was added, false otherwise
+ */
+static bool add_if_absent(address value, address* list, int list_capacity) {
+  for (int i = 0; i < list_capacity; i++) {
+    if (list[i] == value) {
+      return false;
+    }
+    if (list[i] == nullptr) {
+      list[i] = value;
+      if (i + 1 < list_capacity) {
+        list[i + 1] = nullptr;
+      }
+      return true;
+    }
+  }
+  return false;
+}
+
+/**
+ * Prints the VM generated code unit, if any, containing `pc` if it has not already
+ * been printed. If the code unit is an InterpreterCodelet or StubCodeDesc, it is
+ * only printed if `is_crash_pc` is true.
+ *
+ * @param printed array of code units that have already been printed (delimited by NULL entry)
+ * @param printed_capacity the capacity of `printed`
+ * @return true if the code unit was printed, false otherwise
+ */
+static bool print_code(outputStream* st, Thread* thread, address pc, bool is_crash_pc,
+                       address* printed, int printed_capacity) {
+  if (Interpreter::contains(pc)) {
+    if (is_crash_pc) {
+      // The interpreter CodeBlob is very large so try to print the codelet instead.
+      InterpreterCodelet* codelet = Interpreter::codelet_containing(pc);
+      if (codelet != nullptr) {
+        if (add_if_absent((address) codelet, printed, printed_capacity)) {
+          codelet->print_on(st);
+          Disassembler::decode(codelet->code_begin(), codelet->code_end(), st);
+          return true;
+        }
+      }
+    }
+  } else {
+    StubCodeDesc* desc = StubCodeDesc::desc_for(pc);
+    if (desc != nullptr) {
+      if (is_crash_pc) {
+        if (add_if_absent((address) desc, printed, printed_capacity)) {
+          desc->print_on(st);
+          Disassembler::decode(desc->begin(), desc->end(), st);
+          return true;
+        }
+      }
+    } else if (thread != nullptr) {
+      CodeBlob* cb = CodeCache::find_blob(pc);
+      if (cb != nullptr && add_if_absent((address) cb, printed, printed_capacity)) {
+        // Disassembling nmethod will incur resource memory allocation,
+        // only do so when thread is valid.
+        ResourceMark rm(thread);
+        Disassembler::decode(cb, st);
+        st->cr();
+        return true;
+      }
+    }
+  }
+  return false;
+}
+
+/**
+ * Gets the caller frame of `fr`.
+ *
+ * @returns an invalid frame (i.e. fr.pc() === 0) if the caller cannot be obtained
+ */
+static frame next_frame(frame fr, Thread* t) {
+  // Compiled code may use EBP register on x86 so it looks like
+  // non-walkable C frame. Use frame.sender() for java frames.
+  frame invalid;
+  if (t != nullptr && t->is_Java_thread()) {
+    // Catch very first native frame by using stack address.
+    // For JavaThread stack_base and stack_size should be set.
+    if (!t->is_in_full_stack((address)(fr.real_fp() + 1))) {
+      return invalid;
+    }
+    if (fr.is_java_frame() || fr.is_native_frame() || fr.is_runtime_frame()) {
+      RegisterMap map(JavaThread::cast(t), false); // No update
+      return fr.sender(&map);
+    } else {
+      // is_first_C_frame() does only simple checks for frame pointer,
+      // it will pass if java compiled code has a pointer in EBP.
+      if (os::is_first_C_frame(&fr)) return invalid;
+      return os::get_sender_for_C_frame(&fr);
+    }
+  } else {
+    if (os::is_first_C_frame(&fr)) return invalid;
+    return os::get_sender_for_C_frame(&fr);
+  }
+}
+
 void VMError::print_native_stack(outputStream* st, frame fr, Thread* t, char* buf, int buf_size) {
 
   // see if it's a valid frame
@@ -258,27 +360,10 @@ void VMError::print_native_stack(outputStream* st, frame fr, Thread* t, char* bu
         }
       }
       st->cr();
-      // Compiled code may use EBP register on x86 so it looks like
+      fr = next_frame(fr, t);
-      // non-walkable C frame. Use frame.sender() for java frames.
+      if (fr.pc() == nullptr) {
-      if (t && t->is_Java_thread()) {
-        // Catch very first native frame by using stack address.
-        // For JavaThread stack_base and stack_size should be set.
-        if (!t->is_in_full_stack((address)(fr.real_fp() + 1))) {
         break;
       }
-        if (fr.is_java_frame() || fr.is_native_frame() || fr.is_runtime_frame()) {
-          RegisterMap map(JavaThread::cast(t), false); // No update
-          fr = fr.sender(&map);
-        } else {
-          // is_first_C_frame() does only simple checks for frame pointer,
-          // it will pass if java compiled code has a pointer in EBP.
-          if (os::is_first_C_frame(&fr)) break;
-          fr = os::get_sender_for_C_frame(&fr);
-        }
-      } else {
-        if (os::is_first_C_frame(&fr)) break;
-        fr = os::get_sender_for_C_frame(&fr);
-      }
     }
 
     if (count > StackPrintLimit) {
@@ -747,6 +832,7 @@ void VMError::report(outputStream* st, bool _verbose) {
                            : os::current_frame();
 
        print_native_stack(st, fr, _thread, buf, sizeof(buf));
+       _print_native_stack_used = true;
      }
    }
 
@@ -821,30 +907,28 @@ void VMError::report(outputStream* st, bool _verbose) {
        st->cr();
      }
 
-  STEP("printing code blob if possible")
+  STEP("printing code blobs if possible")
 
      if (_verbose && _context) {
-       CodeBlob* cb = CodeCache::find_blob(_pc);
+       if (!_print_native_stack_used) {
-       if (cb != NULL) {
+         // Only try print code of the crashing frame since
-         if (Interpreter::contains(_pc)) {
+         // we cannot walk the native stack using next_frame.
-           // The interpreter CodeBlob is very large so try to print the codelet instead.
+         const int printed_capacity = 1;
-           InterpreterCodelet* codelet = Interpreter::codelet_containing(_pc);
+         address printed_singleton = nullptr;
-           if (codelet != NULL) {
+         address* printed = &printed_singleton;
-             codelet->print_on(st);
+         print_code(st, _thread, _pc, true, printed, 1);
-             Disassembler::decode(codelet->code_begin(), codelet->code_end(), st);
-           }
        } else {
-           StubCodeDesc* desc = StubCodeDesc::desc_for(_pc);
+         // Print up to the first 5 unique code units on the stack
-           if (desc != NULL) {
+         const int printed_capacity = 5;
-             desc->print_on(st);
+         address printed[printed_capacity];
-             Disassembler::decode(desc->begin(), desc->end(), st);
+         printed[0] = nullptr; // length(list) == index of first nullptr
-           } else if (_thread != NULL) {
+
-             // Disassembling nmethod will incur resource memory allocation,
+         frame fr = os::fetch_frame_from_context(_context);
-             // only do so when thread is valid.
+         for (int count = 0; count < printed_capacity && fr.pc() != nullptr; ) {
-             ResourceMark rm(_thread);
+           if (print_code(st, _thread, fr.pc(), fr.pc() == _pc, printed, printed_capacity)) {
-             Disassembler::decode(cb, st);
+             count++;
-             st->cr();
            }
+           fr = next_frame(fr, _thread);
          }
        }
      }

src/hotspot/share/utilities/vmError.hpp

@@ -51,6 +51,10 @@ class VMError : public AllStatic {
   static void*       _context;          // ContextRecord on Windows,
                                         // ucontext_t on Solaris/Linux
 
+  // records if VMError::print_native_stack was used to
+  // print the native stack instead of os::platform_print_native_stack
+  static bool        _print_native_stack_used;
+
   // additional info for VM internal errors
   static const char* _filename;
   static int         _lineno;

test/hotspot/jtreg/runtime/ErrorHandling/MachCodeFramesInErrorFile.java

@@ -0,0 +1,174 @@
+/*
+ * Copyright (c) 2021, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test
+ * @bug 8272586
+ * @requires vm.compiler2.enabled
+ * @summary Test that abstract machine code is dumped for the top frames in a hs-err log
+ * @library /test/lib
+ * @modules java.base/jdk.internal.misc
+ *          java.compiler
+ *          java.management
+ *          jdk.internal.jvmstat/sun.jvmstat.monitor
+ * @run driver MachCodeFramesInErrorFile
+ */
+
+import java.nio.file.Files;
+import java.nio.file.Path;
+import java.nio.file.Paths;
+import java.util.List;
+import java.util.ArrayList;
+import java.util.stream.Stream;
+import java.util.stream.Collectors;
+import java.util.regex.Pattern;
+import java.util.regex.Matcher;
+
+import jdk.test.lib.process.ProcessTools;
+import jdk.test.lib.process.OutputAnalyzer;
+import jdk.test.lib.Asserts;
+
+import jdk.internal.misc.Unsafe;
+
+public class MachCodeFramesInErrorFile {
+    private static class Crasher {
+        // Need to make unsafe a compile-time constant so that
+        // C2 intrinsifies the call to Unsafe.getLong in method3.
+        private static final Unsafe unsafe = Unsafe.getUnsafe();
+        public static void main(String[] args) {
+            method1(10);
+        }
+
+        static void method1(long address) {
+            System.out.println("in method1");
+            method2(address);
+        }
+        static void method2(long address) {
+            System.out.println("in method2");
+            method3(address);
+        }
+        static void method3(long address) {
+            System.out.println("in method3");
+            // Keep chasing pointers until we crash
+            while (true) {
+                address = unsafe.getLong(address);
+            }
+        }
+    }
+
+    /**
+     * Runs Crasher and tries to force compile the methods in Crasher. The inner
+     * most method crashes the VM with Unsafe. The resulting hs-err log is
+     * expected to have a min number of MachCode sections.
+     */
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder(
+            "-Xmx64m", "--add-exports=java.base/jdk.internal.misc=ALL-UNNAMED",
+            "-XX:-CreateCoredumpOnCrash",
+            "-Xcomp",
+            "-XX:-TieredCompilation", // ensure C2 compiles Crasher.method3
+            "-XX:CompileCommand=compileonly,MachCodeFramesInErrorFile$Crasher.m*",
+            "-XX:CompileCommand=dontinline,MachCodeFramesInErrorFile$Crasher.m*",
+            Crasher.class.getName());
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+
+        // Extract hs_err_pid file.
+        String hs_err_file = output.firstMatch("# *(\\S*hs_err_pid\\d+\\.log)", 1);
+        if (hs_err_file == null) {
+            throw new RuntimeException("Did not find hs_err_pid file in output.\n" +
+                                       "stderr:\n" + output.getStderr() + "\n" +
+                                       "stdout:\n" + output.getStdout());
+        }
+        Path hsErrPath = Paths.get(hs_err_file);
+        if (!Files.exists(hsErrPath)) {
+            throw new RuntimeException("hs_err_pid file missing at " + hsErrPath + ".\n");
+        }
+        String hsErr = Files.readString(hsErrPath);
+        if (!crashedInCrasherMethod(hsErr)) {
+            return;
+        }
+        List<String> nativeFrames = extractNativeFrames(hsErr);
+        int compiledJavaFrames = (int) nativeFrames.stream().filter(f -> f.startsWith("J ")).count();
+
+        Matcher matcher = Pattern.compile("\\[MachCode\\]\\s*\\[Verified Entry Point\\]\\s*  # \\{method\\} \\{[^}]*\\} '([^']+)' '([^']+)' in '([^']+)'", Pattern.DOTALL).matcher(hsErr);
+        List<String> machCodeHeaders = matcher.results().map(mr -> String.format("'%s' '%s' in '%s'", mr.group(1), mr.group(2), mr.group(3))).collect(Collectors.toList());
+        String message = "Mach code headers: " + machCodeHeaders +
+                         "\n\nExtracted MachCode:\n" + extractMachCode(hsErr) +
+                         "\n\nExtracted native frames:\n" + String.join("\n", nativeFrames);
+        int minExpectedMachCodeSections = Math.max(1, compiledJavaFrames);
+        Asserts.assertTrue(machCodeHeaders.size() >= minExpectedMachCodeSections, message);
+    }
+
+    /**
+     * Checks whether the crashing frame is in {@code Crasher.method3}.
+     */
+    private static boolean crashedInCrasherMethod(String hsErr) {
+        boolean checkProblematicFrame = false;
+        for (String line : hsErr.split(System.lineSeparator())) {
+            if (line.startsWith("# Problematic frame:")) {
+                checkProblematicFrame = true;
+            } else if (checkProblematicFrame) {
+                String crasherMethod = Crasher.class.getSimpleName() + ".method3";
+                if (!line.contains(crasherMethod)) {
+                    // There's any number of things that can subvert the attempt
+                    // to crash in the expected method.
+                    System.out.println("Crashed in method other than " + crasherMethod + "\n\n" + line + "\n\nSkipping rest of test.");
+                    return false;
+                }
+                return true;
+            }
+        }
+        throw new RuntimeException("\"# Problematic frame:\" line missing in hs_err_pid file:\n" + hsErr);
+    }
+
+    /**
+     * Gets the lines in {@code hsErr} below the line starting with "Native frames:" up to the next blank line.
+     */
+    private static List<String> extractNativeFrames(String hsErr) {
+        List<String> res = new ArrayList<>();
+        boolean inNativeFrames = false;
+        for (String line : hsErr.split(System.lineSeparator())) {
+            if (line.startsWith("Native frames: ")) {
+                inNativeFrames = true;
+            } else if (inNativeFrames) {
+                if (line.trim().isEmpty()) {
+                    return res;
+                }
+                res.add(line);
+            }
+        }
+        throw new RuntimeException("\"Native frames:\" line missing in hs_err_pid file:\n" + hsErr);
+    }
+
+    private static String extractMachCode(String hsErr) {
+        int start = hsErr.indexOf("[MachCode]");
+        if (start != -1) {
+            int end = hsErr.lastIndexOf("[/MachCode]");
+            if (end != -1) {
+                return hsErr.substring(start, end + "[/MachCode]".length());
+            }
+            return hsErr.substring(start);
+        }
+        return null;
+    }
+}