# HG changeset patch # User lagergren # Date 1415809144 -3600 # Node ID 568ec2feb2285da6d29a8b2e05f83a00488b339d # Parent 3dbb4c9ff43c5581bb9bdb603cec40f0d05976b0 8063036: Various pretty printing issues with --log=recompile Reviewed-by: hannesw, jlaskey diff -r 3dbb4c9ff43c -r 568ec2feb228 src/jdk/nashorn/internal/runtime/CompiledFunction.java --- a/src/jdk/nashorn/internal/runtime/CompiledFunction.java Wed Nov 12 14:12:01 2014 +0100 +++ b/src/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 ipp) { + private static List toStringInvalidations(final Map ipp) { if (ipp == null) { - return ""; + return Collections.emptyList(); } - final StringBuilder sb = new StringBuilder(); + final List list = new ArrayList<>(); for (final Iterator> iter = ipp.entrySet().iterator(); iter.hasNext(); ) { final Map.Entry 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 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 invalidatedProgramPoints) { this.data = data; this.log = data.getLogger(); diff -r 3dbb4c9ff43c -r 568ec2feb228 src/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java --- a/src/jdk/nashorn/internal/runtime/RecompilableScriptFunctionData.java Wed Nov 12 14:12:01 2014 +0100 +++ b/src/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 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()); } /**