From 9d5d9c42858e4410031b5d7867693e8324105a64 Mon Sep 17 00:00:00 2001 From: vlivanov Date: Fri, 5 Oct 2012 18:57:10 -0700 Subject: 7177003: C1: LogCompilation support Summary: add LogCompilation support in C1 - both client and tiered mode. Reviewed-by: twisti, kvn --- src/os/linux/vm/vmError_linux.cpp | 2 +- src/share/vm/c1/c1_Compilation.cpp | 25 ++++++++++++++++-- src/share/vm/c1/c1_Compilation.hpp | 2 ++ src/share/vm/c1/c1_GraphBuilder.cpp | 31 +++++++++++++++++++++-- src/share/vm/c1/c1_GraphBuilder.hpp | 3 ++- src/share/vm/c1/c1_Optimizer.cpp | 30 ++++++++++++++++++++++ src/share/vm/ci/ciEnv.cpp | 3 ++- src/share/vm/compiler/compileBroker.cpp | 3 ++- src/share/vm/compiler/compileLog.cpp | 45 +++++++++++++++++++++++++++++++++ src/share/vm/compiler/compileLog.hpp | 12 +++++++++ src/share/vm/oops/method.cpp | 3 ++- src/share/vm/opto/bytecodeInfo.cpp | 4 +-- src/share/vm/opto/compile.cpp | 3 +++ src/share/vm/opto/parse1.cpp | 6 ++--- src/share/vm/runtime/deoptimization.cpp | 7 +++-- src/share/vm/runtime/globals.hpp | 2 +- src/share/vm/runtime/thread.cpp | 6 +++++ src/share/vm/utilities/ostream.cpp | 2 +- 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("", (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_id); + _log_file->print_cr("", writer_id); } _last_writer = writer_id; } -- cgit v1.2.3