8005079: fix LogCompilation for incremental inlining

Report late inlining as part of the rest of the inlining output

Reviewed-by: twisti, kvn
This commit is contained in:
Roland Westrelin 2014-04-10 11:38:12 +02:00
parent 65d6e6b331
commit 522abfc113
16 changed files with 273 additions and 43 deletions

View File

@ -25,6 +25,7 @@
package com.sun.hotspot.tools.compiler;
import java.io.PrintStream;
import java.util.ArrayDeque;
import java.util.ArrayList;
import java.util.List;
@ -40,6 +41,7 @@ public class CallSite {
private int endNodes;
private int endLiveNodes;
private double timeStamp;
private long inlineId;
CallSite() {
}
@ -94,7 +96,7 @@ public class CallSite {
public void print(PrintStream stream, int indent) {
emit(stream, indent);
String m = getMethod().getHolder().replace('/', '.') + "::" + getMethod().getName();
String m = getMethod().getHolder() + "::" + getMethod().getName();
if (getReason() == null) {
stream.print(" @ " + getBci() + " " + m + " (" + getMethod().getBytes() + " bytes)");
@ -214,4 +216,45 @@ public class CallSite {
return timeStamp;
}
private boolean matches(CallSite other) {
// Every late inline call site has a unique inline id. If the
// call site we're looking for has one then use it other rely
// on method name and bci.
if (other.inlineId != 0) {
return inlineId == other.inlineId;
}
return method.equals(other.method) && bci == other.bci;
}
public CallSite findCallSite(ArrayDeque<CallSite> sites) {
// Locate a late inline call site. Multiple chains of
// identical call sites with the same method name/bci are
// possible so we have to try them all until we find the late
// inline call site that has a matching inline id.
CallSite site = sites.pop();
for (CallSite c : calls) {
if (c.matches(site)) {
if (!sites.isEmpty()) {
CallSite res = c.findCallSite(sites);
if (res != null) {
sites.push(site);
return res;
}
} else {
sites.push(site);
return c;
}
}
}
sites.push(site);
return null;
}
public long getInlineId() {
return inlineId;
}
public void setInlineId(long inlineId) {
this.inlineId = inlineId;
}
}

View File

@ -31,6 +31,7 @@ package com.sun.hotspot.tools.compiler;
import java.io.FileReader;
import java.io.Reader;
import java.util.ArrayDeque;
import java.util.ArrayList;
import java.util.Collections;
import java.util.Comparator;
@ -144,9 +145,12 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
private Stack<CallSite> scopes = new Stack<CallSite>();
private Compilation compile;
private CallSite site;
private CallSite methodHandleSite;
private Stack<Phase> phaseStack = new Stack<Phase>();
private UncommonTrapEvent currentTrap;
private Stack<CallSite> late_inline_scope;
private Stack<CallSite> lateInlineScope;
private boolean lateInlining;
long parseLong(String l) {
try {
@ -330,18 +334,61 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
}
methods.put(id, m);
} else if (qname.equals("call")) {
site = new CallSite(bci, method(search(atts, "method")));
if (methodHandleSite != null) {
methodHandleSite = null;
}
Method m = method(search(atts, "method"));
if (lateInlining && scopes.size() == 0) {
// re-attempting already seen call site (late inlining for MH invokes)
if (m != site.getMethod()) {
if (bci != site.getBci()) {
System.out.println(m + " bci: " + bci);
System.out.println(site.getMethod() + " bci: " + site.getBci());
throw new InternalError("bci mismatch after late inlining");
}
site.setMethod(m);
}
} else {
site = new CallSite(bci, m);
}
site.setCount(Integer.parseInt(search(atts, "count", "0")));
String receiver = atts.getValue("receiver");
if (receiver != null) {
site.setReceiver(type(receiver));
site.setReceiver_count(Integer.parseInt(search(atts, "receiver_count")));
}
scopes.peek().add(site);
int methodHandle = Integer.parseInt(search(atts, "method_handle_intrinsic", "0"));
if (lateInlining && scopes.size() == 0) {
// The call was added before this round of late inlining
} else if (methodHandle == 0) {
scopes.peek().add(site);
} else {
// method handle call site can be followed by another
// call (in case it is inlined). If that happens we
// discard the method handle call site. So we keep
// track of it but don't add it to the list yet.
methodHandleSite = site;
}
} else if (qname.equals("regalloc")) {
compile.setAttempts(Integer.parseInt(search(atts, "attempts")));
} else if (qname.equals("inline_fail")) {
scopes.peek().last().setReason(search(atts, "reason"));
if (methodHandleSite != null) {
scopes.peek().add(methodHandleSite);
methodHandleSite = null;
}
if (lateInlining && scopes.size() == 0) {
site.setReason(search(atts, "reason"));
lateInlining = false;
} else {
scopes.peek().last().setReason(search(atts, "reason"));
}
} else if (qname.equals("inline_success")) {
if (methodHandleSite != null) {
throw new InternalError("method handle site should have been replaced");
}
if (lateInlining && scopes.size() == 0) {
site.setReason(null);
}
} else if (qname.equals("failure")) {
failureReason = search(atts, "reason");
} else if (qname.equals("task_done")) {
@ -371,22 +418,30 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
// ignore for now
}
} else if (qname.equals("late_inline")) {
late_inline_scope = new Stack<CallSite>();
long inlineId = Long.parseLong(search(atts, "inline_id"));
lateInlineScope = new Stack<CallSite>();
site = new CallSite(-999, method(search(atts, "method")));
late_inline_scope.push(site);
site.setInlineId(inlineId);
lateInlineScope.push(site);
} else if (qname.equals("jvms")) {
// <jvms bci='4' method='java/io/DataInputStream readChar ()C' bytes='40' count='5815' iicount='20815'/>
if (currentTrap != null) {
currentTrap.addJVMS(atts.getValue("method"), Integer.parseInt(atts.getValue("bci")));
} else if (late_inline_scope != null) {
} else if (lateInlineScope != null) {
bci = Integer.parseInt(search(atts, "bci"));
site = new CallSite(bci, method(search(atts, "method")));
late_inline_scope.push(site);
lateInlineScope.push(site);
} else {
// Ignore <eliminate_allocation type='667'>,
// <eliminate_lock lock='1'>,
// <replace_string_concat arguments='2' string_alloc='0' multiple='0'>
}
} else if (qname.equals("inline_id")) {
if (methodHandleSite != null) {
throw new InternalError("method handle site should have been replaced");
}
long id = Long.parseLong(search(atts, "id"));
site.setInlineId(id);
} else if (qname.equals("nmethod")) {
String id = makeId(atts);
NMethod nm = new NMethod(Double.parseDouble(search(atts, "stamp")),
@ -396,8 +451,18 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
nmethods.put(id, nm);
events.add(nm);
} else if (qname.equals("parse")) {
if (methodHandleSite != null) {
throw new InternalError("method handle site should have been replaced");
}
Method m = method(search(atts, "method"));
if (scopes.size() == 0) {
if (lateInlining && scopes.size() == 0) {
if (site.getMethod() != m) {
System.out.println(site.getMethod());
System.out.println(m);
throw new InternalError("Unexpected method mismatch during late inlining");
}
}
if (scopes.size() == 0 && !lateInlining) {
compile.setMethod(m);
scopes.push(site);
} else {
@ -427,14 +492,19 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
if (qname.equals("parse")) {
indent -= 2;
scopes.pop();
if (scopes.size() == 0) {
lateInlining = false;
}
} else if (qname.equals("uncommon_trap")) {
currentTrap = null;
} else if (qname.equals("late_inline")) {
// Populate late inlining info.
// late_inline scopes are specified in reverse order:
if (scopes.size() != 0) {
throw new InternalError("scopes should be empty for late inline");
}
// late inline scopes are specified in reverse order:
// compiled method should be on top of stack.
CallSite caller = late_inline_scope.pop();
CallSite caller = lateInlineScope.pop();
Method m = compile.getMethod();
if (m != caller.getMethod()) {
System.out.println(m);
@ -444,28 +514,42 @@ public class LogParser extends DefaultHandler implements ErrorHandler, Constants
// late_inline contains caller+bci info, convert it
// to bci+callee info used by LogCompilation.
site = compile.getLateInlineCall();
CallSite lateInlineSite = compile.getLateInlineCall();
ArrayDeque<CallSite> thisCallScopes = new ArrayDeque<CallSite>();
do {
bci = caller.getBci();
// Next inlined call.
caller = late_inline_scope.pop();
caller = lateInlineScope.pop();
CallSite callee = new CallSite(bci, caller.getMethod());
site.add(callee);
site = callee;
} while (!late_inline_scope.empty());
callee.setInlineId(caller.getInlineId());
thisCallScopes.addLast(callee);
lateInlineSite.add(callee);
lateInlineSite = callee;
} while (!lateInlineScope.empty());
site = compile.getCall().findCallSite(thisCallScopes);
if (site == null) {
System.out.println(caller.getMethod() + " bci: " + bci);
throw new InternalError("couldn't find call site");
}
lateInlining = true;
if (caller.getBci() != -999) {
System.out.println(caller.getMethod());
throw new InternalError("broken late_inline info");
}
if (site.getMethod() != caller.getMethod()) {
System.out.println(site.getMethod());
System.out.println(caller.getMethod());
throw new InternalError("call site and late_inline info don't match");
if (site.getInlineId() == caller.getInlineId()) {
site.setMethod(caller.getMethod());
} else {
System.out.println(site.getMethod());
System.out.println(caller.getMethod());
throw new InternalError("call site and late_inline info don't match");
}
}
// late_inline is followed by parse with scopes.size() == 0,
// 'site' will be pushed to scopes.
late_inline_scope = null;
lateInlineScope = null;
} else if (qname.equals("task")) {
types.clear();
methods.clear();

View File

@ -51,15 +51,15 @@ public class Method implements Constants {
String format(int osr_bci) {
if (osr_bci >= 0) {
return getHolder().replace('/', '.') + "::" + getName() + " @ " + osr_bci + " (" + getBytes() + " bytes)";
return getHolder() + "::" + getName() + " @ " + osr_bci + " (" + getBytes() + " bytes)";
} else {
return getHolder().replace('/', '.') + "::" + getName() + " (" + getBytes() + " bytes)";
return getHolder() + "::" + getName() + " (" + getBytes() + " bytes)";
}
}
@Override
public String toString() {
return getHolder().replace('/', '.') + "::" + getName() + " (" + getBytes() + " bytes)";
return getHolder() + "::" + getName() + " (" + getBytes() + " bytes)";
}
public String getHolder() {
@ -117,4 +117,14 @@ public class Method implements Constants {
public void setFlags(String flags) {
this.flags = flags;
}
@Override
public boolean equals(Object o) {
if (o instanceof Method) {
Method other = (Method)o;
return holder.equals(other.holder) && name.equals(other.name) &&
arguments.equals(other.arguments) && returnType.equals(other.returnType);
}
return false;
}
}

View File

@ -968,6 +968,7 @@ void CodeBuffer::verify_section_allocation() {
void CodeBuffer::log_section_sizes(const char* name) {
if (xtty != NULL) {
ttyLocker ttyl;
// log info about buffer usage
xtty->print_cr("<blob name='%s' size='%d'>", name, _total_size);
for (int n = (int) CodeBuffer::SECT_FIRST; n < (int) CodeBuffer::SECT_LIMIT; n++) {

View File

@ -237,3 +237,9 @@ void ciKlass::print_impl(outputStream* st) {
void ciKlass::print_name_on(outputStream* st) {
name()->print_symbol_on(st);
}
const char* ciKlass::external_name() const {
GUARDED_VM_ENTRY(
return get_Klass()->external_name();
)
}

View File

@ -125,6 +125,8 @@ public:
virtual ciKlass* exact_klass() = 0;
void print_name_on(outputStream* st);
const char* external_name() const;
};
#endif // SHARE_VM_CI_CIKLASS_HPP

View File

@ -123,6 +123,10 @@ void ciSymbol::print_symbol_on(outputStream *st) {
GUARDED_VM_ENTRY(get_symbol()->print_symbol_on(st);)
}
const char* ciSymbol::as_klass_external_name() const {
GUARDED_VM_ENTRY(return get_symbol()->as_klass_external_name(););
}
// ------------------------------------------------------------------
// ciSymbol::make_impl
//

View File

@ -90,6 +90,7 @@ public:
void print_symbol() {
print_symbol_on(tty);
}
const char* as_klass_external_name() const;
// Make a ciSymbol from a C string.
// Consider adding to vmSymbols.hpp instead of using this constructor.

View File

@ -106,7 +106,7 @@ int CompileLog::identify(ciBaseObject* obj) {
if (mobj->is_klass()) {
ciKlass* klass = mobj->as_klass();
begin_elem("klass id='%d'", id);
name(klass->name());
name(klass);
if (!klass->is_loaded()) {
print(" unloaded='1'");
} else {
@ -171,6 +171,15 @@ void CompileLog::name(ciSymbol* name) {
print("'");
}
void CompileLog::name(ciKlass* k) {
print(" name='");
if (!k->is_loaded()) {
text()->print(k->name()->as_klass_external_name());
} else {
text()->print(k->external_name());
}
print("'");
}
// ------------------------------------------------------------------
// CompileLog::clear_identities

View File

@ -28,6 +28,7 @@
#include "utilities/xmlstream.hpp"
class ciBaseObject;
class ciKlass;
class ciObject;
class ciMetadata;
class ciSymbol;
@ -72,6 +73,7 @@ class CompileLog : public xmlStream {
void name(ciSymbol* s); // name='s'
void name(Symbol* s) { xmlStream::name(s); }
void name(ciKlass* k);
// Output an object description, return obj->ident().
int identify(ciBaseObject* obj);

View File

@ -266,14 +266,17 @@ CallGenerator* CallGenerator::for_virtual_call(ciMethod* m, int vtable_index) {
// Allow inlining decisions to be delayed
class LateInlineCallGenerator : public DirectCallGenerator {
private:
// unique id for log compilation
jlong _unique_id;
protected:
CallGenerator* _inline_cg;
virtual bool do_late_inline_check(JVMState* jvms) { return true; }
public:
LateInlineCallGenerator(ciMethod* method, CallGenerator* inline_cg) :
DirectCallGenerator(method, true), _inline_cg(inline_cg) {}
DirectCallGenerator(method, true), _inline_cg(inline_cg), _unique_id(0) {}
virtual bool is_late_inline() const { return true; }
@ -283,6 +286,8 @@ class LateInlineCallGenerator : public DirectCallGenerator {
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
C->log_inline_id(this);
// Record that this call site should be revisited once the main
// parse is finished.
if (!is_mh_late_inline()) {
@ -304,6 +309,14 @@ class LateInlineCallGenerator : public DirectCallGenerator {
C->print_inlining_move_to(this);
C->print_inlining_update_delayed(this);
}
virtual void set_unique_id(jlong id) {
_unique_id = id;
}
virtual jlong unique_id() const {
return _unique_id;
}
};
void LateInlineCallGenerator::do_late_inline() {
@ -368,6 +381,8 @@ void LateInlineCallGenerator::do_late_inline() {
C->print_inlining_move_to(this);
C->log_late_inline(this);
// This check is done here because for_method_handle_inline() method
// needs jvms for inlined state.
if (!do_late_inline_check(jvms)) {
@ -375,17 +390,6 @@ void LateInlineCallGenerator::do_late_inline() {
return;
}
CompileLog* log = C->log();
if (log != NULL) {
log->head("late_inline method='%d'", log->identify(method()));
JVMState* p = jvms;
while (p != NULL) {
log->elem("jvms bci='%d' method='%d'", p->bci(), log->identify(p->method()));
p = p->caller();
}
log->tail("late_inline");
}
// Setup default node notes to be picked up by the inlining
Node_Notes* old_nn = C->default_node_notes();
if (old_nn != NULL) {
@ -438,11 +442,12 @@ class LateInlineMHCallGenerator : public LateInlineCallGenerator {
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
JVMState* new_jvms = LateInlineCallGenerator::generate(jvms, parent_parser);
Compile* C = Compile::current();
if (_input_not_const) {
// inlining won't be possible so no need to enqueue right now.
call_node()->set_generator(this);
} else {
Compile::current()->add_late_inline(this);
C->add_late_inline(this);
}
return new_jvms;
}
@ -483,6 +488,9 @@ class LateInlineStringCallGenerator : public LateInlineCallGenerator {
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
C->log_inline_id(this);
C->add_string_late_inline(this);
JVMState* new_jvms = DirectCallGenerator::generate(jvms, parent_parser);
@ -505,6 +513,8 @@ class LateInlineBoxingCallGenerator : public LateInlineCallGenerator {
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
C->log_inline_id(this);
C->add_boxing_late_inline(this);
JVMState* new_jvms = DirectCallGenerator::generate(jvms, parent_parser);
@ -786,6 +796,7 @@ CallGenerator* CallGenerator::for_method_handle_inline(JVMState* jvms, ciMethod*
} else {
const char* msg = "receiver not constant";
if (PrintInlining) C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
C->log_inline_failure(msg);
}
}
break;
@ -858,6 +869,7 @@ CallGenerator* CallGenerator::for_method_handle_inline(JVMState* jvms, ciMethod*
} else {
const char* msg = "member_name not constant";
if (PrintInlining) C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
C->log_inline_failure(msg);
}
}
break;

View File

@ -84,6 +84,9 @@ class CallGenerator : public ResourceObj {
virtual CallStaticJavaNode* call_node() const { ShouldNotReachHere(); return NULL; }
virtual void set_unique_id(jlong id) { fatal("unique id only for late inlines"); };
virtual jlong unique_id() const { fatal("unique id only for late inlines"); return 0; };
// Note: It is possible for a CG to be both inline and virtual.
// (The hashCode intrinsic does a vtable check and an inlined fast path.)

View File

@ -3851,7 +3851,7 @@ void Compile::print_inlining_assert_ready() {
void Compile::dump_inlining() {
bool do_print_inlining = print_inlining() || print_intrinsics();
if (do_print_inlining) {
if (do_print_inlining || log() != NULL) {
// Print inlining message for candidates that we couldn't inline
// for lack of space
for (int i = 0; i < _late_inlines.length(); i++) {
@ -3861,6 +3861,7 @@ void Compile::dump_inlining() {
if (do_print_inlining) {
cg->print_inlining_late(msg);
}
log_late_inline_failure(cg, msg);
}
}
}
@ -3871,6 +3872,48 @@ void Compile::dump_inlining() {
}
}
void Compile::log_late_inline(CallGenerator* cg) {
if (log() != NULL) {
log()->head("late_inline method='%d' inline_id='" JLONG_FORMAT "'", log()->identify(cg->method()),
cg->unique_id());
JVMState* p = cg->call_node()->jvms();
while (p != NULL) {
log()->elem("jvms bci='%d' method='%d'", p->bci(), log()->identify(p->method()));
p = p->caller();
}
log()->tail("late_inline");
}
}
void Compile::log_late_inline_failure(CallGenerator* cg, const char* msg) {
log_late_inline(cg);
if (log() != NULL) {
log()->inline_fail(msg);
}
}
void Compile::log_inline_id(CallGenerator* cg) {
if (log() != NULL) {
// The LogCompilation tool needs a unique way to identify late
// inline call sites. This id must be unique for this call site in
// this compilation. Try to have it unique across compilations as
// well because it can be convenient when grepping through the log
// file.
// Distinguish OSR compilations from others in case CICountOSR is
// on.
jlong id = ((jlong)unique()) + (((jlong)compile_id()) << 33) + (CICountOSR && is_osr_compilation() ? ((jlong)1) << 32 : 0);
cg->set_unique_id(id);
log()->elem("inline_id id='" JLONG_FORMAT "'", id);
}
}
void Compile::log_inline_failure(const char* msg) {
if (C->log() != NULL) {
C->log()->inline_fail(msg);
}
}
// Dump inlining replay data to the stream.
// Don't change thread state and acquire any locks.
void Compile::dump_inline_data(outputStream* out) {

View File

@ -440,6 +440,8 @@ class Compile : public Phase {
void print_inlining_push();
PrintInliningBuffer& print_inlining_current();
void log_late_inline_failure(CallGenerator* cg, const char* msg);
public:
outputStream* print_inlining_stream() const {
@ -459,6 +461,10 @@ class Compile : public Phase {
print_inlining_stream()->print(ss.as_string());
}
void log_late_inline(CallGenerator* cg);
void log_inline_id(CallGenerator* cg);
void log_inline_failure(const char* msg);
void* replay_inline_data() const { return _replay_inline_data; }
// Dump inlining replay data to the stream.

View File

@ -104,6 +104,9 @@ CallGenerator* Compile::call_generator(ciMethod* callee, int vtable_index, bool
log->print(" receiver2='%d' receiver2_count='%d'", r2id, profile.receiver_count(1));
}
}
if (callee->is_method_handle_intrinsic()) {
log->print(" method_handle_intrinsic='1'");
}
log->end_elem();
}
@ -296,6 +299,7 @@ CallGenerator* Compile::call_generator(ciMethod* callee, int vtable_index, bool
if (call_does_dispatch) {
const char* msg = "virtual call";
if (PrintInlining) print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
C->log_inline_failure(msg);
return CallGenerator::for_virtual_call(callee, vtable_index);
} else {
// Class Hierarchy Analysis or Type Profile reveals a unique target,

View File

@ -396,10 +396,10 @@ void xmlStream::method(methodHandle method) {
}
void xmlStream::method_text(methodHandle method) {
ResourceMark rm;
assert_if_no_error(inside_attrs(), "printing attributes");
if (method.is_null()) return;
//method->print_short_name(text());
method->method_holder()->name()->print_symbol_on(text());
text()->print(method->method_holder()->external_name());
print_raw(" "); // " " is easier for tools to parse than "::"
method->name()->print_symbol_on(text());
print_raw(" "); // separator