8007988: PrintInlining output is inconsistent with incremental inlining

Fix duplicate and conflicting inlining output

Reviewed-by: kvn, vlivanov

hotspot/src/share/vm/opto/callGenerator.cpp

@@ -70,6 +70,7 @@ public:
 
 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 @@ class DirectCallGenerator : public CallGenerator {
 
 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 @@ JVMState* VirtualCallGenerator::generate(JVMState* jvms, Parse* parent_parser) {
   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());
   }
@@ -278,7 +282,6 @@ class LateInlineCallGenerator : public DirectCallGenerator {
 
   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 @@ class LateInlineCallGenerator : public DirectCallGenerator {
   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 @@ void LateInlineCallGenerator::do_late_inline() {
     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 @@ void LateInlineCallGenerator::do_late_inline() {
     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 @@ void LateInlineCallGenerator::do_late_inline() {
     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 @@ class LateInlineMHCallGenerator : public LateInlineCallGenerator {
 
   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 @@ class LateInlineMHCallGenerator : public LateInlineCallGenerator {
     }
     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 @@ class LateInlineStringCallGenerator : public LateInlineCallGenerator {
 
   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 @@ class LateInlineBoxingCallGenerator : public LateInlineCallGenerator {
 
   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 @@ CallGenerator* CallGenerator::for_warm_call(WarmCallInfo* ci,
 
 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 @@ CallGenerator* CallGenerator::for_predicted_call(ciKlass* predicted_receiver,
 
 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 @@ CallGenerator* CallGenerator::for_method_handle_inline(JVMState* jvms, ciMethod*
         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 @@ CallGenerator* CallGenerator::for_method_handle_inline(JVMState* jvms, ciMethod*
           // 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 @@ JVMState* PredictedIntrinsicGenerator::generate(JVMState* jvms, Parse* parent_pa
   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 @@ CallGenerator::for_uncommon_trap(ciMethod* m,
 
 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);

hotspot/src/share/vm/opto/compile.cpp

@@ -662,6 +662,7 @@ Compile::Compile( ciEnv* ci_env, C2Compiler* compiler, ciMethod* target, int osr
                   _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 @@ Compile::Compile( ciEnv* ci_env, C2Compiler* compiler, ciMethod* target, int osr
   PhaseGVN gvn(node_arena(), estimated_size);
   set_initial_gvn(&gvn);
 
-  if (print_inlining() || print_intrinsics()) {
+  print_inlining_init();
-    _print_inlining_list = new (comp_arena())GrowableArray<PrintInliningBuffer>(comp_arena(), 1, 1, PrintInliningBuffer());
-  }
   { // Scope for timing the parser
     TracePhase t3("parse", &_t_parser, true);
 
@@ -967,6 +966,7 @@ Compile::Compile( ciEnv* ci_env,
     _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 @@ void Compile::Optimize() {
   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::ConstantTable::fill_jump_table(CodeBuffer& cb, MachConstantNode* n
   }
 }
 
-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");
+      if (!cg->is_mh_late_inline()) {
-    }
+        const char* msg = "live nodes > LiveNodeCountInliningCutoff";
-    Unique_Node_List useful;
+        if (do_print_inlining) {
-    useful.push(root());
+          cg->print_inlining_late(msg);
-    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 (do_print_inlining) {
     for (int i = 0; i < _print_inlining_list->length(); i++) {
       tty->print(_print_inlining_list->adr_at(i)->ss()->as_string());
     }

hotspot/src/share/vm/opto/compile.hpp

@@ -416,6 +416,7 @@ class Compile : public Phase {
     void set_cg(CallGenerator* cg) { _cg = cg; }
   };
 
+  stringStream* _print_inlining_stream;
   GrowableArray<PrintInliningBuffer>* _print_inlining_list;
   int _print_inlining_idx;
 
@@ -433,33 +434,24 @@ class Compile : public Phase {
 
   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();
+    assert(print_inlining() || print_intrinsics(), "PrintInlining off?");
+    return _print_inlining_stream;
   }
 
-  void print_inlining_skip(CallGenerator* cg) {
+  void print_inlining_update(CallGenerator* cg);
-    if (_print_inlining) {
+  void print_inlining_update_delayed(CallGenerator* cg);
-      _print_inlining_list->adr_at(_print_inlining_idx)->set_cg(cg);
+  void print_inlining_move_to(CallGenerator* cg);
-      _print_inlining_idx++;
+  void print_inlining_assert_ready();
-      _print_inlining_list->insert_before(_print_inlining_idx, PrintInliningBuffer());
+  void print_inlining_reset();
-    }
-  }
-
-  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(ciMethod* method, int inline_level, int bci, const char* msg = NULL) {
     stringStream ss;

hotspot/src/share/vm/opto/doCall.cpp

@@ -294,6 +294,8 @@ CallGenerator* Compile::call_generator(ciMethod* callee, int vtable_index, bool
   // 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 @@ void Parse::do_call() {
   // 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 @@ void Parse::do_call() {
     // 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;
     }

hotspot/src/share/vm/opto/library_call.cpp

@@ -620,6 +620,7 @@ JVMState* LibraryIntrinsic::generate(JVMState* jvms, Parse* parent_parser) {
     }
     // 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 @@ JVMState* LibraryIntrinsic::generate(JVMState* jvms, Parse* parent_parser) {
     }
   }
   C->gather_intrinsic_statistics(intrinsic_id(), is_virtual(), Compile::_intrinsic_failed);
+  C->print_inlining_update(this);
   return NULL;
 }