8063036: Various pretty printing issues with --log=recompile
authorlagergren
Wed, 12 Nov 2014 17:19:04 +0100
changeset 27529 eafb7de4648e
parent 27528 4a61cb4dfc6c
child 27530 518b8ae2dbb9
8063036: Various pretty printing issues with --log=recompile Reviewed-by: hannesw, jlaskey
nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/CompiledFunction.java
nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java
--- a/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/CompiledFunction.java	Wed Nov 12 15:13:08 2014 +0100
+++ b/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/CompiledFunction.java	Wed Nov 12 17:19:04 2014 +0100
@@ -33,9 +33,11 @@
 import java.lang.invoke.MethodType;
 import java.lang.invoke.MutableCallSite;
 import java.lang.invoke.SwitchPoint;
+import java.util.ArrayList;
 import java.util.Collection;
 import java.util.Collections;
 import java.util.Iterator;
+import java.util.List;
 import java.util.Map;
 import java.util.TreeMap;
 import java.util.function.Supplier;
@@ -726,34 +728,58 @@
      * @param ipp
      * @return string describing the ipp map
      */
-    private static String toStringInvalidations(final Map<Integer, Type> ipp) {
+    private static List<String> toStringInvalidations(final Map<Integer, Type> ipp) {
         if (ipp == null) {
-            return "";
+            return Collections.emptyList();
         }
 
-        final StringBuilder sb = new StringBuilder();
+        final List<String> list = new ArrayList<>();
 
         for (final Iterator<Map.Entry<Integer, Type>> iter = ipp.entrySet().iterator(); iter.hasNext(); ) {
             final Map.Entry<Integer, Type> entry = iter.next();
             final char bct = entry.getValue().getBytecodeStackType();
+            final String type;
 
+            switch (entry.getValue().getBytecodeStackType()) {
+            case 'A':
+                type = "object";
+                break;
+            case 'I':
+                type = "int";
+                break;
+            case 'J':
+                type = "long";
+                break;
+            case 'D':
+                type = "double";
+                break;
+            default:
+                type = String.valueOf(bct);
+                break;
+            }
+
+            final StringBuilder sb = new StringBuilder();
             sb.append('[').
+                    append("program point: ").
                     append(entry.getKey()).
-                    append("->").
-                    append(bct == 'A' ? 'O' : bct).
+                    append(" -> ").
+                    append(type).
                     append(']');
 
-            if (iter.hasNext()) {
-                sb.append(' ');
-            }
+            list.add(sb.toString());
         }
 
-        return sb.toString();
+        return list;
     }
 
     private void logRecompile(final String reason, final FunctionNode fn, final MethodType type, final Map<Integer, Type> ipp) {
         if (log.isEnabled()) {
-            log.info(reason, DebugLogger.quote(fn.getName()), " signature: ", type, " ", toStringInvalidations(ipp));
+            log.info(reason, DebugLogger.quote(fn.getName()), " signature: ", type);
+            log.indent();
+            for (final String str : toStringInvalidations(ipp)) {
+                log.fine(str);
+            }
+            log.unindent();
         }
     }
 
@@ -769,7 +795,14 @@
      */
     private synchronized MethodHandle handleRewriteException(final OptimismInfo oldOptInfo, final RewriteException re) {
         if (log.isEnabled()) {
-            log.info(new RecompilationEvent(Level.INFO, re, re.getReturnValueNonDestructive()), "RewriteException ", re.getMessageShort());
+            log.info(
+                    new RecompilationEvent(
+                        Level.INFO,
+                        re,
+                        re.getReturnValueNonDestructive()),
+                    "caught RewriteException ",
+                    re.getMessageShort());
+            log.indent();
         }
 
         final MethodType type = type();
@@ -799,7 +832,7 @@
 
         logRecompile("Deoptimizing recompilation (up to bytecode) ", fn, ct, effectiveOptInfo.invalidatedProgramPoints);
         fn = compiler.compile(fn, serialized ? CompilationPhases.RECOMPILE_SERIALIZED_UPTO_BYTECODE : CompilationPhases.COMPILE_UPTO_BYTECODE);
-        log.info("Reusable IR generated");
+        log.fine("Reusable IR generated");
 
         // compile the rest of the function, and install it
         log.info("Generating and installing bytecode from reusable IR...");
@@ -815,16 +848,16 @@
             compiler.persistClassInfo(cacheKey, normalFn);
         }
 
-        log.info("Done.");
-
         final boolean canBeDeoptimized = normalFn.canBeDeoptimized();
 
         if (log.isEnabled()) {
-            log.info("Recompiled '", fn.getName(), "' (", Debug.id(this), ") ", canBeDeoptimized ? " can still be deoptimized." : " is completely deoptimized.");
+            log.unindent();
+            log.info("Done.");
+
+            log.info("Recompiled '", fn.getName(), "' (", Debug.id(this), ") ", canBeDeoptimized ? "can still be deoptimized." : " is completely deoptimized.");
+            log.finest("Looking up invoker...");
         }
 
-        log.info("Looking up invoker...");
-
         final MethodHandle newInvoker = effectiveOptInfo.data.lookup(fn);
         invoker     = newInvoker.asType(type.changeReturnType(newInvoker.type().returnType()));
         constructor = null; // Will be regenerated when needed
@@ -870,7 +903,6 @@
         private SwitchPoint optimisticAssumptions;
         private final DebugLogger log;
 
-        @SuppressWarnings("unused")
         OptimismInfo(final RecompilableScriptFunctionData data, final Map<Integer, Type> invalidatedProgramPoints) {
             this.data = data;
             this.log  = data.getLogger();
--- a/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java	Wed Nov 12 15:13:08 2014 +0100
+++ b/nashorn/src/jdk.scripting.nashorn/share/classes/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java	Wed Nov 12 17:19:04 2014 +0100
@@ -26,7 +26,6 @@
 package jdk.nashorn.internal.runtime;
 
 import static jdk.nashorn.internal.lookup.Lookup.MH;
-
 import java.io.IOException;
 import java.lang.invoke.MethodHandle;
 import java.lang.invoke.MethodHandles;
@@ -620,20 +619,25 @@
         return f;
     }
 
-    MethodHandle lookup(final FunctionInitializer fnInit) {
+    private void logLookup(final boolean shouldLog, final MethodType targetType) {
+        if (shouldLog && log.isEnabled()) {
+            log.info("Looking up ", DebugLogger.quote(functionName), " type=", targetType);
+        }
+    }
+
+    private MethodHandle lookup(final FunctionInitializer fnInit, final boolean shouldLog) {
         final MethodType type = fnInit.getMethodType();
+        logLookup(shouldLog, type);
         return lookupCodeMethod(fnInit.getCode(), type);
     }
 
     MethodHandle lookup(final FunctionNode fn) {
         final MethodType type = new FunctionSignature(fn).getMethodType();
+        logLookup(true, type);
         return lookupCodeMethod(fn.getCompileUnit().getCode(), type);
     }
 
     MethodHandle lookupCodeMethod(final Class<?> codeClass, final MethodType targetType) {
-        if (log.isEnabled()) {
-            log.info("Looking up ", DebugLogger.quote(functionName), " type=", targetType);
-        }
         return MH.findStatic(LOOKUP, codeClass, functionName, targetType);
     }
 
@@ -649,7 +653,7 @@
         if(!code.isEmpty()) {
             throw new IllegalStateException(name);
         }
-        addCode(lookup(initializer), null, null, initializer.getFlags());
+        addCode(lookup(initializer, true), null, null, initializer.getFlags());
     }
 
     private CompiledFunction addCode(final MethodHandle target, final Map<Integer, Type> invalidatedProgramPoints,
@@ -671,10 +675,10 @@
      */
     private CompiledFunction addCode(final FunctionInitializer fnInit, final MethodType callSiteType) {
         if (isVariableArity()) {
-            return addCode(lookup(fnInit), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags());
+            return addCode(lookup(fnInit, true), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags());
         }
 
-        final MethodHandle handle = lookup(fnInit);
+        final MethodHandle handle = lookup(fnInit, true);
         final MethodType fromType = handle.type();
         MethodType toType = needsCallee(fromType) ? callSiteType.changeParameterType(0, ScriptFunction.class) : callSiteType.dropParameterTypes(0, 1);
         toType = toType.changeReturnType(fromType.returnType());
@@ -699,7 +703,7 @@
             toType = toType.dropParameterTypes(fromCount, toCount);
         }
 
-        return addCode(lookup(fnInit).asType(toType), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags());
+        return addCode(lookup(fnInit, false).asType(toType), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags());
     }
 
     /**