8007988: PrintInlining output is inconsistent with incremental inlining
Summary: fix duplicate and conflicting inlining output
Reviewed-by: kvn, vlivanov
--- a/hotspot/src/share/vm/opto/callGenerator.cpp Tue Apr 08 09:51:25 2014 +0200
+++ b/hotspot/src/share/vm/opto/callGenerator.cpp Wed Apr 09 09:17:43 2014 +0200
@@ -70,6 +70,7 @@
JVMState* ParseGenerator::generate(JVMState* jvms, Parse* parent_parser) {
Compile* C = Compile::current();
+ C->print_inlining_update(this);
if (is_osr()) {
// The JVMS for a OSR has a single argument (see its TypeFunc).
@@ -126,6 +127,7 @@
JVMState* DirectCallGenerator::generate(JVMState* jvms, Parse* parent_parser) {
GraphKit kit(jvms);
+ kit.C->print_inlining_update(this);
bool is_static = method()->is_static();
address target = is_static ? SharedRuntime::get_resolve_static_call_stub()
: SharedRuntime::get_resolve_opt_virtual_call_stub();
@@ -178,6 +180,8 @@
GraphKit kit(jvms);
Node* receiver = kit.argument(0);
+ kit.C->print_inlining_update(this);
+
if (kit.C->log() != NULL) {
kit.C->log()->elem("virtual_call bci='%d'", jvms->bci());
}
@@ -271,14 +275,13 @@
LateInlineCallGenerator(ciMethod* method, CallGenerator* inline_cg) :
DirectCallGenerator(method, true), _inline_cg(inline_cg) {}
- virtual bool is_late_inline() const { return true; }
+ virtual bool is_late_inline() const { return true; }
// Convert the CallStaticJava into an inline
virtual void do_late_inline();
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
- C->print_inlining_skip(this);
// Record that this call site should be revisited once the main
// parse is finished.
@@ -296,10 +299,11 @@
virtual void print_inlining_late(const char* msg) {
CallNode* call = call_node();
Compile* C = Compile::current();
- C->print_inlining_insert(this);
+ C->print_inlining_assert_ready();
C->print_inlining(method(), call->jvms()->depth()-1, call->jvms()->bci(), msg);
+ C->print_inlining_move_to(this);
+ C->print_inlining_update_delayed(this);
}
-
};
void LateInlineCallGenerator::do_late_inline() {
@@ -360,6 +364,10 @@
map->set_argument(jvms, i1, call->in(TypeFunc::Parms + i1));
}
+ C->print_inlining_assert_ready();
+
+ C->print_inlining_move_to(this);
+
// This check is done here because for_method_handle_inline() method
// needs jvms for inlined state.
if (!do_late_inline_check(jvms)) {
@@ -367,8 +375,6 @@
return;
}
- C->print_inlining_insert(this);
-
CompileLog* log = C->log();
if (log != NULL) {
log->head("late_inline method='%d'", log->identify(method()));
@@ -388,7 +394,7 @@
C->set_default_node_notes(entry_nn);
}
- // Now perform the inling using the synthesized JVMState
+ // Now perform the inlining using the synthesized JVMState
JVMState* new_jvms = _inline_cg->generate(jvms, NULL);
if (new_jvms == NULL) return; // no change
if (C->failing()) return;
@@ -431,6 +437,7 @@
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
JVMState* new_jvms = LateInlineCallGenerator::generate(jvms, parent_parser);
+
if (_input_not_const) {
// inlining won't be possible so no need to enqueue right now.
call_node()->set_generator(this);
@@ -439,17 +446,14 @@
}
return new_jvms;
}
-
- virtual void print_inlining_late(const char* msg) {
- if (!_input_not_const) return;
- LateInlineCallGenerator::print_inlining_late(msg);
- }
};
bool LateInlineMHCallGenerator::do_late_inline_check(JVMState* jvms) {
CallGenerator* cg = for_method_handle_inline(jvms, _caller, method(), _input_not_const);
+ Compile::current()->print_inlining_update_delayed(this);
+
if (!_input_not_const) {
_attempt++;
}
@@ -479,8 +483,6 @@
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
- C->print_inlining_skip(this);
-
C->add_string_late_inline(this);
JVMState* new_jvms = DirectCallGenerator::generate(jvms, parent_parser);
@@ -502,7 +504,6 @@
virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
Compile *C = Compile::current();
- C->print_inlining_skip(this);
C->add_boxing_late_inline(this);
@@ -554,6 +555,8 @@
JVMState* WarmCallGenerator::generate(JVMState* jvms, Parse* parent_parser) {
Compile* C = Compile::current();
+ C->print_inlining_update(this);
+
if (C->log() != NULL) {
C->log()->elem("warm_call bci='%d'", jvms->bci());
}
@@ -632,6 +635,7 @@
JVMState* PredictedCallGenerator::generate(JVMState* jvms, Parse* parent_parser) {
GraphKit kit(jvms);
+ kit.C->print_inlining_update(this);
PhaseGVN& gvn = kit.gvn();
// We need an explicit receiver null_check before checking its type.
// We share a map with the caller, so his JVMS gets adjusted.
@@ -779,6 +783,9 @@
assert(cg == NULL || !cg->is_late_inline() || cg->is_mh_late_inline(), "no late inline here");
if (cg != NULL && cg->is_inline())
return cg;
+ } else {
+ const char* msg = "receiver not constant";
+ if (PrintInlining) C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
}
}
break;
@@ -844,11 +851,13 @@
// provide us with a type
speculative_receiver_type = receiver_type->speculative_type();
}
-
CallGenerator* cg = C->call_generator(target, vtable_index, call_does_dispatch, jvms, true, PROB_ALWAYS, speculative_receiver_type, true, true);
assert(cg == NULL || !cg->is_late_inline() || cg->is_mh_late_inline(), "no late inline here");
if (cg != NULL && cg->is_inline())
return cg;
+ } else {
+ const char* msg = "member_name not constant";
+ if (PrintInlining) C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
}
}
break;
@@ -904,6 +913,7 @@
if (kit.failing())
return NULL; // might happen because of NodeCountInliningCutoff
+ kit.C->print_inlining_update(this);
SafePointNode* slow_map = NULL;
JVMState* slow_jvms;
if (slow_ctl != NULL) {
@@ -1017,6 +1027,7 @@
JVMState* UncommonTrapCallGenerator::generate(JVMState* jvms, Parse* parent_parser) {
GraphKit kit(jvms);
+ kit.C->print_inlining_update(this);
// Take the trap with arguments pushed on the stack. (Cf. null_check_receiver).
int nargs = method()->arg_size();
kit.inc_sp(nargs);
--- a/hotspot/src/share/vm/opto/compile.cpp Tue Apr 08 09:51:25 2014 +0200
+++ b/hotspot/src/share/vm/opto/compile.cpp Wed Apr 09 09:17:43 2014 +0200
@@ -662,6 +662,7 @@
_inlining_progress(false),
_inlining_incrementally(false),
_print_inlining_list(NULL),
+ _print_inlining_stream(NULL),
_print_inlining_idx(0),
_preserve_jvm_state(0) {
C = this;
@@ -723,9 +724,7 @@
PhaseGVN gvn(node_arena(), estimated_size);
set_initial_gvn(&gvn);
- if (print_inlining() || print_intrinsics()) {
- _print_inlining_list = new (comp_arena())GrowableArray<PrintInliningBuffer>(comp_arena(), 1, 1, PrintInliningBuffer());
- }
+ print_inlining_init();
{ // Scope for timing the parser
TracePhase t3("parse", &_t_parser, true);
@@ -967,6 +966,7 @@
_inlining_progress(false),
_inlining_incrementally(false),
_print_inlining_list(NULL),
+ _print_inlining_stream(NULL),
_print_inlining_idx(0),
_preserve_jvm_state(0),
_allowed_reasons(0) {
@@ -2023,6 +2023,8 @@
ResourceMark rm;
int loop_opts_cnt;
+ print_inlining_reinit();
+
NOT_PRODUCT( verify_graph_edges(); )
print_method(PHASE_AFTER_PARSING);
@@ -3755,30 +3757,114 @@
}
}
-void Compile::dump_inlining() {
+// The message about the current inlining is accumulated in
+// _print_inlining_stream and transfered into the _print_inlining_list
+// once we know whether inlining succeeds or not. For regular
+// inlining, messages are appended to the buffer pointed by
+// _print_inlining_idx in the _print_inlining_list. For late inlining,
+// a new buffer is added after _print_inlining_idx in the list. This
+// way we can update the inlining message for late inlining call site
+// when the inlining is attempted again.
+void Compile::print_inlining_init() {
+ if (print_inlining() || print_intrinsics()) {
+ _print_inlining_stream = new stringStream();
+ _print_inlining_list = new (comp_arena())GrowableArray<PrintInliningBuffer>(comp_arena(), 1, 1, PrintInliningBuffer());
+ }
+}
+
+void Compile::print_inlining_reinit() {
+ if (print_inlining() || print_intrinsics()) {
+ // Re allocate buffer when we change ResourceMark
+ _print_inlining_stream = new stringStream();
+ }
+}
+
+void Compile::print_inlining_reset() {
+ _print_inlining_stream->reset();
+}
+
+void Compile::print_inlining_commit() {
+ assert(print_inlining() || print_intrinsics(), "PrintInlining off?");
+ // Transfer the message from _print_inlining_stream to the current
+ // _print_inlining_list buffer and clear _print_inlining_stream.
+ _print_inlining_list->at(_print_inlining_idx).ss()->write(_print_inlining_stream->as_string(), _print_inlining_stream->size());
+ print_inlining_reset();
+}
+
+void Compile::print_inlining_push() {
+ // Add new buffer to the _print_inlining_list at current position
+ _print_inlining_idx++;
+ _print_inlining_list->insert_before(_print_inlining_idx, PrintInliningBuffer());
+}
+
+Compile::PrintInliningBuffer& Compile::print_inlining_current() {
+ return _print_inlining_list->at(_print_inlining_idx);
+}
+
+void Compile::print_inlining_update(CallGenerator* cg) {
if (print_inlining() || print_intrinsics()) {
+ if (!cg->is_late_inline()) {
+ if (print_inlining_current().cg() != NULL) {
+ print_inlining_push();
+ }
+ print_inlining_commit();
+ } else {
+ if (print_inlining_current().cg() != cg &&
+ (print_inlining_current().cg() != NULL ||
+ print_inlining_current().ss()->size() != 0)) {
+ print_inlining_push();
+ }
+ print_inlining_commit();
+ print_inlining_current().set_cg(cg);
+ }
+ }
+}
+
+void Compile::print_inlining_move_to(CallGenerator* cg) {
+ // We resume inlining at a late inlining call site. Locate the
+ // corresponding inlining buffer so that we can update it.
+ if (print_inlining()) {
+ for (int i = 0; i < _print_inlining_list->length(); i++) {
+ if (_print_inlining_list->adr_at(i)->cg() == cg) {
+ _print_inlining_idx = i;
+ return;
+ }
+ }
+ ShouldNotReachHere();
+ }
+}
+
+void Compile::print_inlining_update_delayed(CallGenerator* cg) {
+ if (print_inlining()) {
+ assert(_print_inlining_stream->size() > 0, "missing inlining msg");
+ assert(print_inlining_current().cg() == cg, "wrong entry");
+ // replace message with new message
+ _print_inlining_list->at_put(_print_inlining_idx, PrintInliningBuffer());
+ print_inlining_commit();
+ print_inlining_current().set_cg(cg);
+ }
+}
+
+void Compile::print_inlining_assert_ready() {
+ assert(!_print_inlining || _print_inlining_stream->size() == 0, "loosing data");
+}
+
+void Compile::dump_inlining() {
+ bool do_print_inlining = print_inlining() || print_intrinsics();
+ if (do_print_inlining) {
// Print inlining message for candidates that we couldn't inline
- // for lack of space or non constant receiver
+ // for lack of space
for (int i = 0; i < _late_inlines.length(); i++) {
CallGenerator* cg = _late_inlines.at(i);
- cg->print_inlining_late("live nodes > LiveNodeCountInliningCutoff");
- }
- Unique_Node_List useful;
- useful.push(root());
- for (uint next = 0; next < useful.size(); ++next) {
- Node* n = useful.at(next);
- if (n->is_Call() && n->as_Call()->generator() != NULL && n->as_Call()->generator()->call_node() == n) {
- CallNode* call = n->as_Call();
- CallGenerator* cg = call->generator();
- cg->print_inlining_late("receiver not constant");
- }
- uint max = n->len();
- for ( uint i = 0; i < max; ++i ) {
- Node *m = n->in(i);
- if ( m == NULL ) continue;
- useful.push(m);
+ if (!cg->is_mh_late_inline()) {
+ const char* msg = "live nodes > LiveNodeCountInliningCutoff";
+ if (do_print_inlining) {
+ cg->print_inlining_late(msg);
+ }
}
}
+ }
+ if (do_print_inlining) {
for (int i = 0; i < _print_inlining_list->length(); i++) {
tty->print(_print_inlining_list->adr_at(i)->ss()->as_string());
}
--- a/hotspot/src/share/vm/opto/compile.hpp Tue Apr 08 09:51:25 2014 +0200
+++ b/hotspot/src/share/vm/opto/compile.hpp Wed Apr 09 09:17:43 2014 +0200
@@ -416,6 +416,7 @@
void set_cg(CallGenerator* cg) { _cg = cg; }
};
+ stringStream* _print_inlining_stream;
GrowableArray<PrintInliningBuffer>* _print_inlining_list;
int _print_inlining_idx;
@@ -433,33 +434,24 @@
void* _replay_inline_data; // Pointer to data loaded from file
+ void print_inlining_init();
+ void print_inlining_reinit();
+ void print_inlining_commit();
+ void print_inlining_push();
+ PrintInliningBuffer& print_inlining_current();
+
public:
outputStream* print_inlining_stream() const {
- return _print_inlining_list->adr_at(_print_inlining_idx)->ss();
- }
-
- void print_inlining_skip(CallGenerator* cg) {
- if (_print_inlining) {
- _print_inlining_list->adr_at(_print_inlining_idx)->set_cg(cg);
- _print_inlining_idx++;
- _print_inlining_list->insert_before(_print_inlining_idx, PrintInliningBuffer());
- }
+ assert(print_inlining() || print_intrinsics(), "PrintInlining off?");
+ return _print_inlining_stream;
}
- void print_inlining_insert(CallGenerator* cg) {
- if (_print_inlining) {
- for (int i = 0; i < _print_inlining_list->length(); i++) {
- if (_print_inlining_list->adr_at(i)->cg() == cg) {
- _print_inlining_list->insert_before(i+1, PrintInliningBuffer());
- _print_inlining_idx = i+1;
- _print_inlining_list->adr_at(i)->set_cg(NULL);
- return;
- }
- }
- ShouldNotReachHere();
- }
- }
+ void print_inlining_update(CallGenerator* cg);
+ void print_inlining_update_delayed(CallGenerator* cg);
+ void print_inlining_move_to(CallGenerator* cg);
+ void print_inlining_assert_ready();
+ void print_inlining_reset();
void print_inlining(ciMethod* method, int inline_level, int bci, const char* msg = NULL) {
stringStream ss;
--- a/hotspot/src/share/vm/opto/doCall.cpp Tue Apr 08 09:51:25 2014 +0200
+++ b/hotspot/src/share/vm/opto/doCall.cpp Wed Apr 09 09:17:43 2014 +0200
@@ -294,6 +294,8 @@
// There was no special inlining tactic, or it bailed out.
// Use a more generic tactic, like a simple call.
if (call_does_dispatch) {
+ const char* msg = "virtual call";
+ if (PrintInlining) print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
return CallGenerator::for_virtual_call(callee, vtable_index);
} else {
// Class Hierarchy Analysis or Type Profile reveals a unique target,
@@ -396,6 +398,8 @@
// our contribution to it is cleaned up right here.
kill_dead_locals();
+ C->print_inlining_assert_ready();
+
// Set frequently used booleans
const bool is_virtual = bc() == Bytecodes::_invokevirtual;
const bool is_virtual_or_interface = is_virtual || bc() == Bytecodes::_invokeinterface;
@@ -531,7 +535,8 @@
// intrinsic was expecting to optimize. Should always be possible to
// get a normal java call that may inline in that case
cg = C->call_generator(cg->method(), vtable_index, call_does_dispatch, jvms, try_inline, prof_factor(), speculative_receiver_type, /* allow_intrinsics= */ false);
- if ((new_jvms = cg->generate(jvms, this)) == NULL) {
+ new_jvms = cg->generate(jvms, this);
+ if (new_jvms == NULL) {
guarantee(failing(), "call failed to generate: calls should work");
return;
}
--- a/hotspot/src/share/vm/opto/library_call.cpp Tue Apr 08 09:51:25 2014 +0200
+++ b/hotspot/src/share/vm/opto/library_call.cpp Wed Apr 09 09:17:43 2014 +0200
@@ -620,6 +620,7 @@
}
// Push the result from the inlined method onto the stack.
kit.push_result();
+ C->print_inlining_update(this);
return kit.transfer_exceptions_into_jvms();
}
@@ -637,6 +638,7 @@
}
}
C->gather_intrinsic_statistics(intrinsic_id(), is_virtual(), Compile::_intrinsic_failed);
+ C->print_inlining_update(this);
return NULL;
}