Wed, 12 Nov 2014 17:19:04 +0100
8063036: Various pretty printing issues with --log=recompile
Reviewed-by: hannesw, jlaskey
1.1 --- a/src/jdk/nashorn/internal/runtime/CompiledFunction.java Wed Nov 12 14:12:01 2014 +0100 1.2 +++ b/src/jdk/nashorn/internal/runtime/CompiledFunction.java Wed Nov 12 17:19:04 2014 +0100 1.3 @@ -33,9 +33,11 @@ 1.4 import java.lang.invoke.MethodType; 1.5 import java.lang.invoke.MutableCallSite; 1.6 import java.lang.invoke.SwitchPoint; 1.7 +import java.util.ArrayList; 1.8 import java.util.Collection; 1.9 import java.util.Collections; 1.10 import java.util.Iterator; 1.11 +import java.util.List; 1.12 import java.util.Map; 1.13 import java.util.TreeMap; 1.14 import java.util.function.Supplier; 1.15 @@ -726,34 +728,58 @@ 1.16 * @param ipp 1.17 * @return string describing the ipp map 1.18 */ 1.19 - private static String toStringInvalidations(final Map<Integer, Type> ipp) { 1.20 + private static List<String> toStringInvalidations(final Map<Integer, Type> ipp) { 1.21 if (ipp == null) { 1.22 - return ""; 1.23 + return Collections.emptyList(); 1.24 } 1.25 1.26 - final StringBuilder sb = new StringBuilder(); 1.27 + final List<String> list = new ArrayList<>(); 1.28 1.29 for (final Iterator<Map.Entry<Integer, Type>> iter = ipp.entrySet().iterator(); iter.hasNext(); ) { 1.30 final Map.Entry<Integer, Type> entry = iter.next(); 1.31 final char bct = entry.getValue().getBytecodeStackType(); 1.32 + final String type; 1.33 1.34 + switch (entry.getValue().getBytecodeStackType()) { 1.35 + case 'A': 1.36 + type = "object"; 1.37 + break; 1.38 + case 'I': 1.39 + type = "int"; 1.40 + break; 1.41 + case 'J': 1.42 + type = "long"; 1.43 + break; 1.44 + case 'D': 1.45 + type = "double"; 1.46 + break; 1.47 + default: 1.48 + type = String.valueOf(bct); 1.49 + break; 1.50 + } 1.51 + 1.52 + final StringBuilder sb = new StringBuilder(); 1.53 sb.append('['). 1.54 + append("program point: "). 1.55 append(entry.getKey()). 1.56 - append("->"). 1.57 - append(bct == 'A' ? 'O' : bct). 1.58 + append(" -> "). 1.59 + append(type). 1.60 append(']'); 1.61 1.62 - if (iter.hasNext()) { 1.63 - sb.append(' '); 1.64 - } 1.65 + list.add(sb.toString()); 1.66 } 1.67 1.68 - return sb.toString(); 1.69 + return list; 1.70 } 1.71 1.72 private void logRecompile(final String reason, final FunctionNode fn, final MethodType type, final Map<Integer, Type> ipp) { 1.73 if (log.isEnabled()) { 1.74 - log.info(reason, DebugLogger.quote(fn.getName()), " signature: ", type, " ", toStringInvalidations(ipp)); 1.75 + log.info(reason, DebugLogger.quote(fn.getName()), " signature: ", type); 1.76 + log.indent(); 1.77 + for (final String str : toStringInvalidations(ipp)) { 1.78 + log.fine(str); 1.79 + } 1.80 + log.unindent(); 1.81 } 1.82 } 1.83 1.84 @@ -769,7 +795,14 @@ 1.85 */ 1.86 private synchronized MethodHandle handleRewriteException(final OptimismInfo oldOptInfo, final RewriteException re) { 1.87 if (log.isEnabled()) { 1.88 - log.info(new RecompilationEvent(Level.INFO, re, re.getReturnValueNonDestructive()), "RewriteException ", re.getMessageShort()); 1.89 + log.info( 1.90 + new RecompilationEvent( 1.91 + Level.INFO, 1.92 + re, 1.93 + re.getReturnValueNonDestructive()), 1.94 + "caught RewriteException ", 1.95 + re.getMessageShort()); 1.96 + log.indent(); 1.97 } 1.98 1.99 final MethodType type = type(); 1.100 @@ -799,7 +832,7 @@ 1.101 1.102 logRecompile("Deoptimizing recompilation (up to bytecode) ", fn, ct, effectiveOptInfo.invalidatedProgramPoints); 1.103 fn = compiler.compile(fn, serialized ? CompilationPhases.RECOMPILE_SERIALIZED_UPTO_BYTECODE : CompilationPhases.COMPILE_UPTO_BYTECODE); 1.104 - log.info("Reusable IR generated"); 1.105 + log.fine("Reusable IR generated"); 1.106 1.107 // compile the rest of the function, and install it 1.108 log.info("Generating and installing bytecode from reusable IR..."); 1.109 @@ -815,16 +848,16 @@ 1.110 compiler.persistClassInfo(cacheKey, normalFn); 1.111 } 1.112 1.113 - log.info("Done."); 1.114 - 1.115 final boolean canBeDeoptimized = normalFn.canBeDeoptimized(); 1.116 1.117 if (log.isEnabled()) { 1.118 - log.info("Recompiled '", fn.getName(), "' (", Debug.id(this), ") ", canBeDeoptimized ? " can still be deoptimized." : " is completely deoptimized."); 1.119 + log.unindent(); 1.120 + log.info("Done."); 1.121 + 1.122 + log.info("Recompiled '", fn.getName(), "' (", Debug.id(this), ") ", canBeDeoptimized ? "can still be deoptimized." : " is completely deoptimized."); 1.123 + log.finest("Looking up invoker..."); 1.124 } 1.125 1.126 - log.info("Looking up invoker..."); 1.127 - 1.128 final MethodHandle newInvoker = effectiveOptInfo.data.lookup(fn); 1.129 invoker = newInvoker.asType(type.changeReturnType(newInvoker.type().returnType())); 1.130 constructor = null; // Will be regenerated when needed 1.131 @@ -870,7 +903,6 @@ 1.132 private SwitchPoint optimisticAssumptions; 1.133 private final DebugLogger log; 1.134 1.135 - @SuppressWarnings("unused") 1.136 OptimismInfo(final RecompilableScriptFunctionData data, final Map<Integer, Type> invalidatedProgramPoints) { 1.137 this.data = data; 1.138 this.log = data.getLogger();
2.1 --- a/src/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java Wed Nov 12 14:12:01 2014 +0100 2.2 +++ b/src/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java Wed Nov 12 17:19:04 2014 +0100 2.3 @@ -26,7 +26,6 @@ 2.4 package jdk.nashorn.internal.runtime; 2.5 2.6 import static jdk.nashorn.internal.lookup.Lookup.MH; 2.7 - 2.8 import java.io.IOException; 2.9 import java.lang.invoke.MethodHandle; 2.10 import java.lang.invoke.MethodHandles; 2.11 @@ -620,20 +619,25 @@ 2.12 return f; 2.13 } 2.14 2.15 - MethodHandle lookup(final FunctionInitializer fnInit) { 2.16 + private void logLookup(final boolean shouldLog, final MethodType targetType) { 2.17 + if (shouldLog && log.isEnabled()) { 2.18 + log.info("Looking up ", DebugLogger.quote(functionName), " type=", targetType); 2.19 + } 2.20 + } 2.21 + 2.22 + private MethodHandle lookup(final FunctionInitializer fnInit, final boolean shouldLog) { 2.23 final MethodType type = fnInit.getMethodType(); 2.24 + logLookup(shouldLog, type); 2.25 return lookupCodeMethod(fnInit.getCode(), type); 2.26 } 2.27 2.28 MethodHandle lookup(final FunctionNode fn) { 2.29 final MethodType type = new FunctionSignature(fn).getMethodType(); 2.30 + logLookup(true, type); 2.31 return lookupCodeMethod(fn.getCompileUnit().getCode(), type); 2.32 } 2.33 2.34 MethodHandle lookupCodeMethod(final Class<?> codeClass, final MethodType targetType) { 2.35 - if (log.isEnabled()) { 2.36 - log.info("Looking up ", DebugLogger.quote(functionName), " type=", targetType); 2.37 - } 2.38 return MH.findStatic(LOOKUP, codeClass, functionName, targetType); 2.39 } 2.40 2.41 @@ -649,7 +653,7 @@ 2.42 if(!code.isEmpty()) { 2.43 throw new IllegalStateException(name); 2.44 } 2.45 - addCode(lookup(initializer), null, null, initializer.getFlags()); 2.46 + addCode(lookup(initializer, true), null, null, initializer.getFlags()); 2.47 } 2.48 2.49 private CompiledFunction addCode(final MethodHandle target, final Map<Integer, Type> invalidatedProgramPoints, 2.50 @@ -671,10 +675,10 @@ 2.51 */ 2.52 private CompiledFunction addCode(final FunctionInitializer fnInit, final MethodType callSiteType) { 2.53 if (isVariableArity()) { 2.54 - return addCode(lookup(fnInit), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags()); 2.55 + return addCode(lookup(fnInit, true), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags()); 2.56 } 2.57 2.58 - final MethodHandle handle = lookup(fnInit); 2.59 + final MethodHandle handle = lookup(fnInit, true); 2.60 final MethodType fromType = handle.type(); 2.61 MethodType toType = needsCallee(fromType) ? callSiteType.changeParameterType(0, ScriptFunction.class) : callSiteType.dropParameterTypes(0, 1); 2.62 toType = toType.changeReturnType(fromType.returnType()); 2.63 @@ -699,7 +703,7 @@ 2.64 toType = toType.dropParameterTypes(fromCount, toCount); 2.65 } 2.66 2.67 - return addCode(lookup(fnInit).asType(toType), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags()); 2.68 + return addCode(lookup(fnInit, false).asType(toType), fnInit.getInvalidatedProgramPoints(), callSiteType, fnInit.getFlags()); 2.69 } 2.70 2.71 /**