[GR-71950] Add better logging of interpreter frames during crash

PullRequest: graal/22822

Author: gilles-duboscq

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/CodeInfoAccess.java

@@ -24,6 +24,8 @@
  */
 package com.oracle.svm.core.code;
 
+import static com.oracle.svm.core.Uninterruptible.CALLED_FROM_UNINTERRUPTIBLE_CODE;
+
 import org.graalvm.nativeimage.c.function.CodePointer;
 import org.graalvm.nativeimage.c.struct.SizeOf;
 import org.graalvm.word.UnsignedWord;
@@ -46,8 +48,6 @@
 import jdk.graal.compiler.api.replacements.Fold;
 import jdk.graal.compiler.word.Word;
 
-import static com.oracle.svm.core.Uninterruptible.CALLED_FROM_UNINTERRUPTIBLE_CODE;
-
 /**
  * Provides functionality to query information about a unit of compiled code from a {@link CodeInfo}
  * object. This helper class is necessary to ensure that {@link CodeInfo} objects are used
@@ -365,10 +365,6 @@ public static void setEncodings(CodeInfo info, NonmovableObjectArray<Object> obj
         }
     }
 
-    public static Log log(CodeInfo info, Log log) {
-        return info.isNull() ? log.string("null") : log.string("CodeInfo@").hex(info);
-    }
-
     @Uninterruptible(reason = "Called from uninterruptible code.", mayBeInlined = true)
     public static int getTier(CodeInfo info) {
         return cast(info).getTier();

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/CodeInfoDecoder.java

@@ -167,8 +167,12 @@ public static void visitObjectReferences(Pointer sp, CodePointer ip, CodeInfo in
 
     @Uninterruptible(reason = "Not really uninterruptible, but we are about to fail.", calleeMustBe = false)
     public static RuntimeException fatalErrorNoReferenceMap(Pointer sp, CodePointer ip, CodeInfo info) {
-        Log.log().string("ip: ").zhex(ip).string(", sp: ").zhex(sp).string(", ");
-        CodeInfoAccess.log(info, Log.log()).newline();
+        Log.log().string("ip: ").zhex(ip).string(", sp: ").zhex(sp).string(", code info: ");
+        if (info.isNull()) {
+            Log.log().string("null");
+        } else {
+            CodeInfoAccess.printCodeInfo(Log.log(), info, true);
+        }
         throw VMError.shouldNotReachHere("No reference map information found");
     }
 

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/CodeInfoTable.java

@@ -114,6 +114,10 @@ public static final class ValueInfo {
         protected long data;
         protected JavaConstant value;
 
+        public ValueInfo() {
+            clear();
+        }
+
         /**
          * Returns the type of the value, describing how to access the value.
          */
@@ -186,6 +190,17 @@ public ValueInfo copyForElement(JavaKind javaKind, int offset) {
             copy.value = value;
             return copy;
         }
+
+        @Uninterruptible(reason = CALLED_FROM_UNINTERRUPTIBLE_CODE, mayBeInlined = true)
+        public void clear() {
+            type = null;
+            kind = null;
+            isCompressedReference = false;
+            isEliminatedMonitor = false;
+            isAutoBoxedPrimitive = false;
+            data = 0;
+            value = null;
+        }
     }
 
     protected FrameInfoQueryResult caller;

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/code/FrameInfoQueryResult.java

@@ -41,7 +41,9 @@
 import com.oracle.svm.core.code.FrameInfoQueryResult;
 import com.oracle.svm.core.code.FrameSourceInfo;
 import com.oracle.svm.core.heap.ObjectReferenceVisitor;
+import com.oracle.svm.core.heap.RestrictHeapAccess;
 import com.oracle.svm.core.heap.UnknownPrimitiveField;
+import com.oracle.svm.core.log.Log;
 
 import jdk.graal.compiler.api.replacements.Fold;
 import jdk.vm.ci.meta.ResolvedJavaMethod;
@@ -79,6 +81,14 @@ public static InterpreterSupport singleton() {
      */
     public abstract FrameSourceInfo getInterpretedMethodFrameInfo(FrameInfoQueryResult frameInfo, Pointer sp);
 
+    /**
+     * Make a best-effort attempt at logging helpful information about the
+     * {@linkplain #isInterpreterRoot interpreter frame}. Avoiding allocations or anything risky
+     * during crash logging.
+     */
+    @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Used for crash log")
+    public abstract void logInterpreterFrame(Log log, FrameInfoQueryResult frameInfo, Pointer sp);
+
     @Platforms(Platform.HOSTED_ONLY.class)
     public static void setLeaveStubPointer(CFunctionPointer leaveStubPointer, int length) {
         assert singleton().leaveStubPointer == null : "multiple leave stub methods registered";

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/interpreter/InterpreterSupport.java

@@ -34,13 +34,15 @@
 import com.oracle.svm.core.code.CodeInfoAccess;
 import com.oracle.svm.core.code.CodeInfoDecoder;
 import com.oracle.svm.core.code.CodeInfoTable;
+import com.oracle.svm.core.code.FrameInfoDecoder;
 import com.oracle.svm.core.code.FrameInfoQueryResult;
 import com.oracle.svm.core.code.ImageCodeInfo;
 import com.oracle.svm.core.code.UntetheredCodeInfo;
 import com.oracle.svm.core.deopt.DeoptimizationSupport;
 import com.oracle.svm.core.deopt.DeoptimizedFrame;
 import com.oracle.svm.core.heap.RestrictHeapAccess;
 import com.oracle.svm.core.imagelayer.ImageLayerBuildingSupport;
+import com.oracle.svm.core.interpreter.InterpreterSupport;
 import com.oracle.svm.core.log.Log;
 
 import jdk.graal.compiler.word.Word;
@@ -87,12 +89,23 @@ private static void logFrame(Log log, Pointer sp, CodePointer ip) {
     public static class StackFramePrintVisitor extends ParameterizedStackFrameVisitor {
         private static final int MAX_STACK_FRAMES_PER_THREAD_TO_PRINT = 100_000;
 
-        private final CodeInfoDecoder.FrameInfoCursor frameInfoCursor = new CodeInfoDecoder.FrameInfoCursor();
+        private final CodeInfoDecoder.FrameInfoCursor frameInfoCursor;
         private int invocationCount;
         private int printedFrames;
         private Pointer expectedSP;
 
         public StackFramePrintVisitor() {
+            FrameInfoDecoder.ValueInfoAllocator valueInfoAllocator;
+            if (InterpreterSupport.isEnabled()) {
+                /*
+                 * This helps print interpreter frames: InterpreterSupportImpl needs value info for
+                 * the method and bci.
+                 */
+                valueInfoAllocator = new CodeInfoDecoder.SingleShotValueInfoAllocator();
+            } else {
+                valueInfoAllocator = CodeInfoDecoder.DummyValueInfoAllocator.SINGLETON;
+            }
+            frameInfoCursor = new CodeInfoDecoder.FrameInfoCursor(valueInfoAllocator);
         }
 
         @SuppressWarnings("hiding")
@@ -160,7 +173,7 @@ private void logDeoptimizedJavaFrame(Log log, Pointer sp, CodePointer ip, Deopti
                 boolean isCompilationRoot = frame.getCaller() == null;
                 printFrameIdentifier(log, Word.nullPointer(), deoptFrame, isCompilationRoot, false);
                 logFrameRaw(log, sp, ip, deoptFrame.getSourceTotalFrameSize());
-                logFrameInfo(log, frame.getFrameInfo(), ImageCodeInfo.CODE_INFO_NAME + ", deopt");
+                logFrameInfo(log, frame.getFrameInfo(), ImageCodeInfo.CODE_INFO_NAME + ", deopt", sp);
                 if (!isCompilationRoot) {
                     log.newline();
                 }
@@ -202,7 +215,7 @@ private void logVirtualFrame(Log log, Pointer sp, CodePointer ip, CodeInfo codeI
             logJavaFrameMinimalInfo(log, sp, ip, codeInfo, null, isCompilationRoot);
 
             String codeInfoName = DeoptimizationSupport.enabled() ? CodeInfoAccess.getName(codeInfo) : null;
-            logFrameInfo(log, frameInfo, codeInfoName);
+            logFrameInfo(log, frameInfo, codeInfoName, sp);
         }
 
         private void logJavaFrameMinimalInfo(Log log, Pointer sp, CodePointer ip, CodeInfo codeInfo, DeoptimizedFrame deoptFrame, boolean isCompilationRoot) {
@@ -261,11 +274,14 @@ private static void logSPAndIP(Log log, Pointer sp, CodePointer ip) {
             log.string("IP ").zhex(ip);
         }
 
-        private static void logFrameInfo(Log log, FrameInfoQueryResult frameInfo, String runtimeMethodInfoName) {
+        private void logFrameInfo(Log log, FrameInfoQueryResult frameInfo, String runtimeMethodInfoName, Pointer sp) {
             if (runtimeMethodInfoName != null) {
                 log.string("[").string(runtimeMethodInfoName).string("] ");
             }
             frameInfo.log(log);
+            if (InterpreterSupport.isEnabled() && invocationCount == 1 && InterpreterSupport.singleton().isInterpreterRoot(frameInfo)) {
+                InterpreterSupport.singleton().logInterpreterFrame(log, frameInfo, sp);
+            }
         }
 
         private static void printFrameIdentifier(Log log, CodeInfo codeInfo, DeoptimizedFrame deoptFrame, boolean isCompilationRoot, boolean isNative) {

substratevm/src/com.oracle.svm.core/src/com/oracle/svm/core/stack/ThreadStackPrinter.java

@@ -36,16 +36,23 @@
 import com.oracle.svm.core.code.FrameInfoQueryResult;
 import com.oracle.svm.core.code.FrameSourceInfo;
 import com.oracle.svm.core.heap.ReferenceAccess;
+import com.oracle.svm.core.heap.RestrictHeapAccess;
 import com.oracle.svm.core.interpreter.InterpreterFrameSourceInfo;
 import com.oracle.svm.core.interpreter.InterpreterSupport;
+import com.oracle.svm.core.log.Log;
 import com.oracle.svm.core.util.VMError;
+import com.oracle.svm.espresso.classfile.descriptors.ByteSequence;
+import com.oracle.svm.espresso.classfile.descriptors.Name;
+import com.oracle.svm.espresso.classfile.descriptors.Symbol;
 import com.oracle.svm.interpreter.metadata.InterpreterResolvedJavaMethod;
 
 import jdk.graal.compiler.word.Word;
 import jdk.vm.ci.meta.LineNumberTable;
 import jdk.vm.ci.meta.ResolvedJavaMethod;
 
 public final class InterpreterSupportImpl extends InterpreterSupport {
+    private static final int MAX_SYMBOL_LOG_LENGTH = 255;
+
     private final int bciSlot;
     private final int interpretedMethodSlot;
     private final int interpretedFrameSlot;
@@ -135,6 +142,93 @@ public FrameSourceInfo getInterpretedMethodFrameInfo(FrameInfoQueryResult frameI
         throw VMError.shouldNotReachHereAtRuntime();
     }
 
+    @Override
+    @RestrictHeapAccess(access = RestrictHeapAccess.Access.NO_ALLOCATION, reason = "Used for crash log")
+    public void logInterpreterFrame(Log log, FrameInfoQueryResult frameInfo, Pointer sp) {
+        if (isInterpreterIntrinsicRoot(frameInfo)) {
+            logInterpreterIntrinsicFrame(log, frameInfo, sp);
+        } else if (isInterpreterBytecodeRoot(frameInfo)) {
+            logInterpreterBytecodeFrame(log, frameInfo, sp);
+        } else {
+            throw VMError.shouldNotReachHereAtRuntime();
+        }
+    }
+
+    private void logInterpreterBytecodeFrame(Log log, FrameInfoQueryResult frameInfo, Pointer sp) {
+        if (!frameInfo.hasLocalValueInfo()) {
+            log.string("  missing local value info (bytecode)");
+            return;
+        }
+        InterpreterResolvedJavaMethod interpretedMethod = readInterpretedMethod(frameInfo, sp);
+        if (interpretedMethod == null) {
+            log.string("  no interpreter method (bytecode)");
+            return;
+        }
+        int bci = readBCI(frameInfo, sp);
+        logInterpreterMethod(log, interpretedMethod, bci);
+    }
+
+    private void logInterpreterIntrinsicFrame(Log log, FrameInfoQueryResult frameInfo, Pointer sp) {
+        if (!frameInfo.hasLocalValueInfo()) {
+            log.string("  missing local value info (intrinsic)");
+            return;
+        }
+        InterpreterResolvedJavaMethod intrinsicMethod = readIntrinsicMethod(frameInfo, sp);
+        if (intrinsicMethod == null) {
+            log.string("  no interpreter method (intrinsic)");
+            return;
+        }
+        logInterpreterMethod(log, intrinsicMethod, -1);
+    }
+
+    private static void logInterpreterMethod(Log log, InterpreterResolvedJavaMethod interpretedMethod, int bci) {
+        String sourceHolderName = interpretedMethod.getDeclaringClass().getJavaClass().getName();
+        Symbol<Name> sourceMethodName = interpretedMethod.getSymbolicName();
+        LineNumberTable lineNumberTable = interpretedMethod.getLineNumberTable();
+        int sourceLineNumber = -1; // unknown
+        if (lineNumberTable != null && bci >= 0) {
+            sourceLineNumber = lineNumberTable.getLineNumber(bci);
+        }
+        log.spaces(2);
+        log.string(sourceHolderName);
+        log.character('.');
+        logSymbol(log, sourceMethodName);
+        String sourceFileName = interpretedMethod.getDeclaringClass().getSourceFileName();
+        if (sourceFileName == null && sourceLineNumber >= 0) {
+            sourceFileName = "Unknown Source";
+        }
+        if (sourceFileName != null) {
+            log.character('(');
+            log.string(sourceFileName);
+            if (sourceLineNumber >= 0) {
+                log.string(":");
+                log.signed(sourceLineNumber);
+            }
+            log.character(')');
+        }
+        if (bci >= 0) {
+            log.spaces(1);
+            log.string("@bci ");
+            log.signed(bci);
+        }
+    }
+
+    private static void logSymbol(Log log, ByteSequence byteSequence) {
+        int length = Math.min(byteSequence.length(), MAX_SYMBOL_LOG_LENGTH);
+        for (int i = 0; i < length; i++) {
+            int b = byteSequence.unsignedByteAt(i);
+            if (0x20 <= b && b <= 0x7e) {
+                // only log printable ascii
+                log.character((char) b);
+            } else {
+                log.character('?');
+            }
+        }
+        if (byteSequence.length() > MAX_SYMBOL_LOG_LENGTH) {
+            log.string("...");
+        }
+    }
+
     @Platforms(Platform.HOSTED_ONLY.class)
     @Override
     public void buildMethodIdMapping(ResolvedJavaMethod[] encodedMethods) {