7177003: C1: LogCompilation support

Summary: add LogCompilation support in C1 - both client and tiered mode.
Reviewed-by: twisti, kvn

18 files changed, 170 insertions, 19 deletions

diff --git a/src/os/linux/vm/vmError_linux.cpp b/src/os/linux/vm/vmError_linux.cpp
index 8ec6ca04c..378c9a6ab 100644
--- a/src/os/linux/vm/vmError_linux.cpp
+++ b/src/os/linux/vm/vmError_linux.cpp
@@ -44,7 +44,7 @@ void VMError::show_message_box(char *buf, int buflen) {
     jio_snprintf(p, buflen - len,
                "\n\n"
                "Do you want to debug the problem?\n\n"
-               "To debug, run 'gdb /proc/%d/exe %d'; then switch to thread " INTX_FORMAT " (" INTPTR_FORMAT ")\n"
+               "To debug, run 'gdb /proc/%d/exe %d'; then switch to thread " UINTX_FORMAT " (" INTPTR_FORMAT ")\n"
                "Enter 'yes' to launch gdb automatically (PATH must include gdb)\n"
                "Otherwise, press RETURN to abort...",
                os::current_process_id(), os::current_process_id(),
diff --git a/src/share/vm/c1/c1_Compilation.cpp b/src/share/vm/c1/c1_Compilation.cpp
index b0ef8dc04..987b00a18 100644
--- a/src/share/vm/c1/c1_Compilation.cpp
+++ b/src/share/vm/c1/c1_Compilation.cpp
@@ -32,6 +32,7 @@
 #include "c1/c1_ValueMap.hpp"
 #include "c1/c1_ValueStack.hpp"
 #include "code/debugInfoRec.hpp"
+#include "compiler/compileLog.hpp"
 
 
 typedef enum {
@@ -67,10 +68,25 @@ static int totalInstructionNodes = 0;
 class PhaseTraceTime: public TraceTime {
  private:
   JavaThread* _thread;
+  CompileLog* _log;
 
  public:
-  PhaseTraceTime(TimerName timer):
-    TraceTime("", &timers[timer], CITime || CITimeEach, Verbose) {
+  PhaseTraceTime(TimerName timer)
+  : TraceTime("", &timers[timer], CITime || CITimeEach, Verbose), _log(NULL) {
+    if (Compilation::current() != NULL) {
+      _log = Compilation::current()->log();
+    }
+
+    if (_log != NULL) {
+      _log->begin_head("phase name='%s'", timer_name[timer]);
+      _log->stamp();
+      _log->end_head();
+    }
+  }
+
+  ~PhaseTraceTime() {
+    if (_log != NULL)
+      _log->done("phase");
   }
 };
 
@@ -390,6 +406,10 @@ void Compilation::compile_method() {
     PhaseTraceTime timeit(_t_codeinstall);
     install_code(frame_size);
   }
+
+  if (log() != NULL) // Print code cache state into compiler log
+    log()->code_cache_state();
+
   totalInstructionNodes += Instruction::number_of_instructions();
 }
 
@@ -456,6 +476,7 @@ Compilation::Compilation(AbstractCompiler* compiler, ciEnv* env, ciMethod* metho
                          int osr_bci, BufferBlob* buffer_blob)
 : _compiler(compiler)
 , _env(env)
+, _log(env->log())
 , _method(method)
 , _osr_bci(osr_bci)
 , _hir(NULL)
diff --git a/src/share/vm/c1/c1_Compilation.hpp b/src/share/vm/c1/c1_Compilation.hpp
index d5c224afd..9a8ca61b8 100644
--- a/src/share/vm/c1/c1_Compilation.hpp
+++ b/src/share/vm/c1/c1_Compilation.hpp
@@ -66,6 +66,7 @@ class Compilation: public StackObj {
   int _next_block_id;
   AbstractCompiler*  _compiler;
   ciEnv*             _env;
+  CompileLog*        _log;
   ciMethod*          _method;
   int                _osr_bci;
   IR*                _hir;
@@ -123,6 +124,7 @@ class Compilation: public StackObj {
 
   // accessors
   ciEnv* env() const                             { return _env; }
+  CompileLog* log() const                        { return _log; }
   AbstractCompiler* compiler() const             { return _compiler; }
   bool has_exception_handlers() const            { return _has_exception_handlers; }
   bool has_fpu_code() const                      { return _has_fpu_code; }
diff --git a/src/share/vm/c1/c1_GraphBuilder.cpp b/src/share/vm/c1/c1_GraphBuilder.cpp
index 95d99025b..1bbdc5afb 100644
--- a/src/share/vm/c1/c1_GraphBuilder.cpp
+++ b/src/share/vm/c1/c1_GraphBuilder.cpp
@@ -1682,6 +1682,12 @@ void GraphBuilder::invoke(Bytecodes::Code code) {
   ciInstanceKlass* callee_holder = ciEnv::get_instance_klass_for_declared_method_holder(holder);
   ciInstanceKlass* actual_recv = callee_holder;
 
+  CompileLog* log = compilation()->log();
+  if (log != NULL)
+      log->elem("call method='%d' instr='%s'",
+                log->identify(target),
+                Bytecodes::name(code));
+
   // Some methods are obviously bindable without any type checks so
   // convert them directly to an invokespecial or invokestatic.
   if (target->is_loaded() && !target->is_abstract() && target->can_be_statically_bound()) {
@@ -1826,6 +1832,7 @@ void GraphBuilder::invoke(Bytecodes::Code code) {
     }
     code = Bytecodes::_invokespecial;
   }
+
   // check if we could do inlining
   if (!PatchALot && Inline && klass->is_loaded() &&
       (klass->is_initialized() || klass->is_interface() && target->holder()->is_initialized())
@@ -2448,6 +2455,7 @@ BlockEnd* GraphBuilder::iterate_bytecodes_for_block(int bci) {
 #endif
   _skip_block = false;
   assert(state() != NULL, "ValueStack missing!");
+  CompileLog* log = compilation()->log();
   ciBytecodeStream s(method());
   s.reset_to_bci(bci);
   int prev_bci = bci;
@@ -2466,6 +2474,9 @@ BlockEnd* GraphBuilder::iterate_bytecodes_for_block(int bci) {
          (block_at(s.cur_bci()) == NULL || block_at(s.cur_bci()) == block())) {
     assert(state()->kind() == ValueStack::Parsing, "invalid state kind");
 
+    if (log != NULL)
+      log->set_context("bc code='%d' bci='%d'", (int)code, s.cur_bci());
+
     // Check for active jsr during OSR compilation
     if (compilation()->is_osr_compile()
         && scope()->is_top_scope()
@@ -2686,8 +2697,13 @@ BlockEnd* GraphBuilder::iterate_bytecodes_for_block(int bci) {
       case Bytecodes::_breakpoint     : BAILOUT_("concurrent setting of breakpoint", NULL);
       default                         : ShouldNotReachHere(); break;
     }
+
+    if (log != NULL)
+      log->clear_context(); // skip marker if nothing was printed
+
     // save current bci to setup Goto at the end
     prev_bci = s.cur_bci();
+
   }
   CHECK_BAILOUT_(NULL);
   // stop processing of this block (see try_inline_full)
@@ -3667,7 +3683,7 @@ bool GraphBuilder::try_inline_full(ciMethod* callee, bool holder_known, Bytecode
       INLINE_BAILOUT("total inlining greater than DesiredMethodLimit");
     }
     // printing
-    print_inlining(callee, "");
+    print_inlining(callee);
   }
 
   // NOTE: Bailouts from this point on, which occur at the
@@ -4133,8 +4149,19 @@ void GraphBuilder::append_unsafe_CAS(ciMethod* callee) {
 
 
 void GraphBuilder::print_inlining(ciMethod* callee, const char* msg, bool success) {
+  CompileLog* log = compilation()->log();
+  if (log != NULL) {
+    if (success) {
+      if (msg != NULL)
+        log->inline_success(msg);
+      else
+        log->inline_success("receiver is statically known");
+    } else {
+      log->inline_fail(msg);
+    }
+  }
+
   if (!PrintInlining)  return;
-  assert(msg != NULL, "must be");
   CompileTask::print_inlining(callee, scope()->level(), bci(), msg);
   if (success && CIPrintMethodCodes) {
     callee->print_codes();
diff --git a/src/share/vm/c1/c1_GraphBuilder.hpp b/src/share/vm/c1/c1_GraphBuilder.hpp
index 09970583c..5f9e40723 100644
--- a/src/share/vm/c1/c1_GraphBuilder.hpp
+++ b/src/share/vm/c1/c1_GraphBuilder.hpp
@@ -31,6 +31,7 @@
 #include "c1/c1_ValueStack.hpp"
 #include "ci/ciMethodData.hpp"
 #include "ci/ciStreams.hpp"
+#include "compiler/compileLog.hpp"
 
 class MemoryBuffer;
 
@@ -369,7 +370,7 @@ class GraphBuilder VALUE_OBJ_CLASS_SPEC {
   void append_unsafe_CAS(ciMethod* callee);
   bool append_unsafe_get_and_set_obj(ciMethod* callee, bool is_add);
 
-  void print_inlining(ciMethod* callee, const char* msg, bool success = true);
+  void print_inlining(ciMethod* callee, const char* msg = NULL, bool success = true);
 
   void profile_call(ciMethod* callee, Value recv, ciKlass* predicted_holder);
   void profile_invocation(ciMethod* inlinee, ValueStack* state);
diff --git a/src/share/vm/c1/c1_Optimizer.cpp b/src/share/vm/c1/c1_Optimizer.cpp
index 3ba17653d..a80989d62 100644
--- a/src/share/vm/c1/c1_Optimizer.cpp
+++ b/src/share/vm/c1/c1_Optimizer.cpp
@@ -29,6 +29,7 @@
 #include "c1/c1_ValueSet.hpp"
 #include "c1/c1_ValueStack.hpp"
 #include "utilities/bitMap.inline.hpp"
+#include "compiler/compileLog.hpp"
 
 define_array(ValueSetArray, ValueSet*);
 define_stack(ValueSetList, ValueSetArray);
@@ -54,7 +55,18 @@ class CE_Eliminator: public BlockClosure {
       // substituted some ifops/phis, so resolve the substitution
       SubstitutionResolver sr(_hir);
     }
+
+    CompileLog* log = _hir->compilation()->log();
+    if (log != NULL)
+      log->set_context("optimize name='cee'");
+  }
+
+  ~CE_Eliminator() {
+    CompileLog* log = _hir->compilation()->log();
+    if (log != NULL)
+      log->clear_context(); // skip marker if nothing was printed
   }
+
   int cee_count() const                          { return _cee_count; }
   int ifop_count() const                         { return _ifop_count; }
 
@@ -306,6 +318,15 @@ class BlockMerger: public BlockClosure {
   , _merge_count(0)
   {
     _hir->iterate_preorder(this);
+    CompileLog* log = _hir->compilation()->log();
+    if (log != NULL)
+      log->set_context("optimize name='eliminate_blocks'");
+  }
+
+  ~BlockMerger() {
+    CompileLog* log = _hir->compilation()->log();
+    if (log != NULL)
+      log->clear_context(); // skip marker if nothing was printed
   }
 
   bool try_merge(BlockBegin* block) {
@@ -574,6 +595,15 @@ class NullCheckEliminator: public ValueVisitor {
     , _work_list(new BlockList()) {
     _visitable_instructions = new ValueSet();
     _visitor.set_eliminator(this);
+    CompileLog* log = _opt->ir()->compilation()->log();
+    if (log != NULL)
+      log->set_context("optimize name='null_check_elimination'");
+  }
+
+  ~NullCheckEliminator() {
+    CompileLog* log = _opt->ir()->compilation()->log();
+    if (log != NULL)
+      log->clear_context(); // skip marker if nothing was printed
   }
 
   Optimizer*  opt()                               { return _opt; }
diff --git a/src/share/vm/ci/ciEnv.cpp b/src/share/vm/ci/ciEnv.cpp
index a895e97d0..605bdbb3a 100644
--- a/src/share/vm/ci/ciEnv.cpp
+++ b/src/share/vm/ci/ciEnv.cpp
@@ -1126,7 +1126,8 @@ void ciEnv::record_method_not_compilable(const char* reason, bool all_tiers) {
       if (all_tiers) {
         log()->elem("method_not_compilable");
       } else {
-        log()->elem("method_not_compilable_at_tier");
+        log()->elem("method_not_compilable_at_tier level='%d'",
+                    current()->task()->comp_level());
       }
     }
     _compilable = new_compilable;
diff --git a/src/share/vm/compiler/compileBroker.cpp b/src/share/vm/compiler/compileBroker.cpp
index 02086da4a..b1e10d652 100644
--- a/src/share/vm/compiler/compileBroker.cpp
+++ b/src/share/vm/compiler/compileBroker.cpp
@@ -1570,7 +1570,8 @@ void CompileBroker::compiler_thread_loop() {
   }
   CompileLog* log = thread->log();
   if (log != NULL) {
-    log->begin_elem("start_compile_thread thread='" UINTX_FORMAT "' process='%d'",
+    log->begin_elem("start_compile_thread name='%s' thread='" UINTX_FORMAT "' process='%d'",
+                    thread->name(),
                     os::current_thread_id(),
                     os::current_process_id());
     log->stamp();
diff --git a/src/share/vm/compiler/compileLog.cpp b/src/share/vm/compiler/compileLog.cpp
index 9d9c76060..e02e4e547 100644
--- a/src/share/vm/compiler/compileLog.cpp
+++ b/src/share/vm/compiler/compileLog.cpp
@@ -302,3 +302,48 @@ void CompileLog::finish_log(outputStream* file) {
   char buf[4 * K];
   finish_log_on_error(file, buf, sizeof(buf));
 }
+
+// ------------------------------------------------------------------
+// CompileLog::inline_success
+//
+// Print about successful method inlining.
+void CompileLog::inline_success(const char* reason) {
+  begin_elem("inline_success reason='");
+  text(reason);
+  end_elem("'");
+}
+
+// ------------------------------------------------------------------
+// CompileLog::inline_fail
+//
+// Print about failed method inlining.
+void CompileLog::inline_fail(const char* reason) {
+  begin_elem("inline_fail reason='");
+  text(reason);
+  end_elem("'");
+}
+
+// ------------------------------------------------------------------
+// CompileLog::set_context
+//
+// Set XML tag as an optional marker - it is printed only if
+// there are other entries after until it is reset.
+void CompileLog::set_context(const char* format, ...) {
+  va_list ap;
+  va_start(ap, format);
+  clear_context();
+  _context.print("<");
+  _context.vprint(format, ap);
+  _context.print_cr("/>");
+  va_end(ap);
+}
+
+// ------------------------------------------------------------------
+// CompileLog::code_cache_state
+//
+// Print code cache state.
+void CompileLog::code_cache_state() {
+  begin_elem("code_cache");
+  CodeCache::log_state(this);
+  end_elem("");
+}
diff --git a/src/share/vm/compiler/compileLog.hpp b/src/share/vm/compiler/compileLog.hpp
index 4dffb2b46..1af5e9143 100644
--- a/src/share/vm/compiler/compileLog.hpp
+++ b/src/share/vm/compiler/compileLog.hpp
@@ -62,7 +62,13 @@ class CompileLog : public xmlStream {
 
   intx          thread_id()                      { return _thread_id; }
   const char*   file()                           { return _file; }
+
+  // Optional context marker, to help place actions that occur during
+  // parsing. If there is no log output until the next context string
+  // or reset, context string will be silently ignored
   stringStream* context()                        { return &_context; }
+  void    clear_context()                        { context()->reset(); }
+  void      set_context(const char* format, ...);
 
   void          name(ciSymbol* s);               // name='s'
   void          name(Symbol* s)                  { xmlStream::name(s); }
@@ -71,6 +77,9 @@ class CompileLog : public xmlStream {
   int           identify(ciBaseObject* obj);
   void          clear_identities();
 
+  void inline_fail   (const char* reason);
+  void inline_success(const char* reason);
+
   // virtuals
   virtual void see_tag(const char* tag, bool push);
   virtual void pop_tag(const char* tag);
@@ -78,6 +87,9 @@ class CompileLog : public xmlStream {
   // make a provisional end of log mark
   void mark_file_end() { _file_end = out()->count(); }
 
+  // Print code cache statistics
+  void code_cache_state();
+
   // copy all logs to the given stream
   static void finish_log(outputStream* out);
   static void finish_log_on_error(outputStream* out, char *buf, int buflen);
diff --git a/src/share/vm/oops/method.cpp b/src/share/vm/oops/method.cpp
index d57f5df26..da2678a5c 100644
--- a/src/share/vm/oops/method.cpp
+++ b/src/share/vm/oops/method.cpp
@@ -712,7 +712,8 @@ void Method::print_made_not_compilable(int comp_level, bool is_osr, bool report)
   }
   if ((TraceDeoptimization || LogCompilation) && (xtty != NULL)) {
     ttyLocker ttyl;
-    xtty->begin_elem("make_not_%scompilable thread='%d'", is_osr ? "osr_" : "", (int) os::current_thread_id());
+    xtty->begin_elem("make_not_%scompilable thread='" UINTX_FORMAT "'",
+                     is_osr ? "osr_" : "", os::current_thread_id());
     xtty->method(this);
     xtty->stamp();
     xtty->end_elem();
diff --git a/src/share/vm/opto/bytecodeInfo.cpp b/src/share/vm/opto/bytecodeInfo.cpp
index 00632a239..a357cceb3 100644
--- a/src/share/vm/opto/bytecodeInfo.cpp
+++ b/src/share/vm/opto/bytecodeInfo.cpp
@@ -439,9 +439,7 @@ WarmCallInfo* InlineTree::ok_to_inline(ciMethod* callee_method, JVMState* jvms,
   WarmCallInfo wci = *(initial_wci);
   failure_msg = try_to_inline(callee_method, caller_method, caller_bci, profile, &wci);
   if (failure_msg != NULL && C->log() != NULL) {
-    C->log()->begin_elem("inline_fail reason='");
-    C->log()->text("%s", failure_msg);
-    C->log()->end_elem("'");
+    C->log()->inline_fail(failure_msg);
   }
 
 #ifndef PRODUCT
diff --git a/src/share/vm/opto/compile.cpp b/src/share/vm/opto/compile.cpp
index 36933f976..cefd4674c 100644
--- a/src/share/vm/opto/compile.cpp
+++ b/src/share/vm/opto/compile.cpp
@@ -828,6 +828,9 @@ Compile::Compile( ciEnv* ci_env, C2Compiler* compiler, ciMethod* target, int osr
                            has_unsafe_access(),
                            SharedRuntime::is_wide_vector(max_vector_size())
                            );
+
+    if (log() != NULL) // Print code cache state into compiler log
+      log()->code_cache_state();
   }
 }
 
diff --git a/src/share/vm/opto/parse1.cpp b/src/share/vm/opto/parse1.cpp
index c3daeecc8..d0b52f554 100644
--- a/src/share/vm/opto/parse1.cpp
+++ b/src/share/vm/opto/parse1.cpp
@@ -1381,8 +1381,7 @@ void Parse::do_one_block() {
       // that occur during parsing of this BC.  If there is no log
       // output until the next context string, this context string
       // will be silently ignored.
-      log->context()->reset();
-      log->context()->print_cr("<bc code='%d' bci='%d'/>", (int)bc(), bci());
+      log->set_context("bc code='%d' bci='%d'", (int)bc(), bci());
     }
 
     if (block()->has_trap_at(bci())) {
@@ -1411,7 +1410,8 @@ void Parse::do_one_block() {
 
     NOT_PRODUCT( parse_histogram()->record_change(); );
 
-    if (log != NULL)  log->context()->reset();  // done w/ this one
+    if (log != NULL)
+      log->clear_context();  // skip marker if nothing was printed
 
     // Fall into next bytecode.  Each bytecode normally has 1 sequential
     // successor which is typically made ready by visiting this bytecode.
diff --git a/src/share/vm/runtime/deoptimization.cpp b/src/share/vm/runtime/deoptimization.cpp
index 4fdd9deda..8650c7dca 100644
--- a/src/share/vm/runtime/deoptimization.cpp
+++ b/src/share/vm/runtime/deoptimization.cpp
@@ -233,6 +233,7 @@ Deoptimization::UnrollBlock* Deoptimization::fetch_unroll_info_helper(JavaThread
         return_value = Handle(thread, result);
         assert(Universe::heap()->is_in_or_null(result), "must be heap pointer");
         if (TraceDeoptimization) {
+          ttyLocker ttyl;
           tty->print_cr("SAVED OOP RESULT " INTPTR_FORMAT " in thread " INTPTR_FORMAT, result, thread);
         }
       }
@@ -493,6 +494,7 @@ Deoptimization::UnrollBlock* Deoptimization::fetch_unroll_info_helper(JavaThread
 
   if (array->frames() > 1) {
     if (VerifyStack && TraceDeoptimization) {
+      ttyLocker ttyl;
       tty->print_cr("Deoptimizing method containing inlining");
     }
   }
@@ -573,6 +575,7 @@ JRT_LEAF(BasicType, Deoptimization::unpack_frames(JavaThread* thread, int exec_m
 
 #ifndef PRODUCT
   if (TraceDeoptimization) {
+    ttyLocker ttyl;
     tty->print_cr("DEOPT UNPACKING thread " INTPTR_FORMAT " vframeArray " INTPTR_FORMAT " mode %d", thread, array, exec_mode);
   }
 #endif
@@ -1322,9 +1325,9 @@ JRT_ENTRY(void, Deoptimization::uncommon_trap_inner(JavaThread* thread, jint tra
       if (TraceDeoptimization) {  // make noise on the tty
         tty->print("Uncommon trap occurred in");
         nm->method()->print_short_name(tty);
-        tty->print(" (@" INTPTR_FORMAT ") thread=%d reason=%s action=%s unloaded_class_index=%d",
+        tty->print(" (@" INTPTR_FORMAT ") thread=" UINTX_FORMAT " reason=%s action=%s unloaded_class_index=%d",
                    fr.pc(),
-                   (int) os::current_thread_id(),
+                   os::current_thread_id(),
                    trap_reason_name(reason),
                    trap_action_name(action),
                    unloaded_class_index);
diff --git a/src/share/vm/runtime/globals.hpp b/src/share/vm/runtime/globals.hpp
index f0c93014f..a0c53aa43 100644
--- a/src/share/vm/runtime/globals.hpp
+++ b/src/share/vm/runtime/globals.hpp
@@ -2332,7 +2332,7 @@ class CommandLineFlags {
   develop(bool, CITimeEach, false,                                          \
           "display timing information after each successful compilation")   \
                                                                             \
-  develop(bool, CICountOSR, true,                                           \
+  develop(bool, CICountOSR, false,                                          \
           "use a separate counter when assigning ids to osr compilations")  \
                                                                             \
   develop(bool, CICompileNatives, true,                                     \
diff --git a/src/share/vm/runtime/thread.cpp b/src/share/vm/runtime/thread.cpp
index d2f819260..d106d2ccd 100644
--- a/src/share/vm/runtime/thread.cpp
+++ b/src/share/vm/runtime/thread.cpp
@@ -2583,6 +2583,12 @@ void JavaThread::deoptimized_wrt_marked_nmethods() {
   StackFrameStream fst(this, UseBiasedLocking);
   for(; !fst.is_done(); fst.next()) {
     if (fst.current()->should_be_deoptimized()) {
+      if (LogCompilation && xtty != NULL) {
+        nmethod* nm = fst.current()->cb()->as_nmethod_or_null();
+        xtty->elem("deoptimized thread='" UINTX_FORMAT "' compile_id='%d'",
+                   this->name(), nm != NULL ? nm->compile_id() : -1);
+      }
+
       Deoptimization::deoptimize(this, *fst.current(), fst.register_map());
     }
   }
diff --git a/src/share/vm/utilities/ostream.cpp b/src/share/vm/utilities/ostream.cpp
index 7fc1ea384..2b6e2eeb8 100644
--- a/src/share/vm/utilities/ostream.cpp
+++ b/src/share/vm/utilities/ostream.cpp
@@ -759,7 +759,7 @@ intx defaultStream::hold(intx writer_id) {
     if (has_log) {
       _log_file->bol();
       // output a hint where this output is coming from:
-      _log_file->print_cr("<writer thread='"INTX_FORMAT"'/>", writer_id);
+      _log_file->print_cr("<writer thread='" UINTX_FORMAT "'/>", writer_id);
     }
     _last_writer = writer_id;
   }