7177003: C1: LogCompilation support
Summary: add LogCompilation support in C1 - both client and tiered mode.
Reviewed-by: twisti, kvn
--- a/hotspot/src/os/linux/vm/vmError_linux.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/os/linux/vm/vmError_linux.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -44,7 +44,7 @@
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(),
--- a/hotspot/src/share/vm/c1/c1_Compilation.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/c1/c1_Compilation.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -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 @@
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 @@
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 @@
int osr_bci, BufferBlob* buffer_blob)
: _compiler(compiler)
, _env(env)
+, _log(env->log())
, _method(method)
, _osr_bci(osr_bci)
, _hir(NULL)
--- a/hotspot/src/share/vm/c1/c1_Compilation.hpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/c1/c1_Compilation.hpp Fri Oct 05 18:57:10 2012 -0700
@@ -66,6 +66,7 @@
int _next_block_id;
AbstractCompiler* _compiler;
ciEnv* _env;
+ CompileLog* _log;
ciMethod* _method;
int _osr_bci;
IR* _hir;
@@ -123,6 +124,7 @@
// 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; }
--- a/hotspot/src/share/vm/c1/c1_GraphBuilder.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/c1/c1_GraphBuilder.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -1682,6 +1682,12 @@
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 @@
}
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 @@
#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 @@
(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 @@
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 @@
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::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();
--- a/hotspot/src/share/vm/c1/c1_GraphBuilder.hpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/c1/c1_GraphBuilder.hpp Fri Oct 05 18:57:10 2012 -0700
@@ -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 @@
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);
--- a/hotspot/src/share/vm/c1/c1_Optimizer.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/c1/c1_Optimizer.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -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 @@
// 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 @@
, _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 @@
, _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; }
--- a/hotspot/src/share/vm/ci/ciEnv.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/ci/ciEnv.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -1126,7 +1126,8 @@
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;
--- a/hotspot/src/share/vm/compiler/compileBroker.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/compiler/compileBroker.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -1570,7 +1570,8 @@
}
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();
--- a/hotspot/src/share/vm/compiler/compileLog.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/compiler/compileLog.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -302,3 +302,48 @@
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("");
+}
--- a/hotspot/src/share/vm/compiler/compileLog.hpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/compiler/compileLog.hpp Fri Oct 05 18:57:10 2012 -0700
@@ -62,7 +62,13 @@
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 @@
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 @@
// 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);
--- a/hotspot/src/share/vm/oops/method.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/oops/method.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -712,7 +712,8 @@
}
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();
--- a/hotspot/src/share/vm/opto/bytecodeInfo.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/opto/bytecodeInfo.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -439,9 +439,7 @@
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
--- a/hotspot/src/share/vm/opto/compile.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/opto/compile.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -828,6 +828,9 @@
has_unsafe_access(),
SharedRuntime::is_wide_vector(max_vector_size())
);
+
+ if (log() != NULL) // Print code cache state into compiler log
+ log()->code_cache_state();
}
}
--- a/hotspot/src/share/vm/opto/parse1.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/opto/parse1.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -1381,8 +1381,7 @@
// 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 @@
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.
--- a/hotspot/src/share/vm/runtime/deoptimization.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/runtime/deoptimization.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -233,6 +233,7 @@
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 @@
if (array->frames() > 1) {
if (VerifyStack && TraceDeoptimization) {
+ ttyLocker ttyl;
tty->print_cr("Deoptimizing method containing inlining");
}
}
@@ -573,6 +575,7 @@
#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 @@
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);
--- a/hotspot/src/share/vm/runtime/globals.hpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/runtime/globals.hpp Fri Oct 05 18:57:10 2012 -0700
@@ -2332,7 +2332,7 @@
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, \
--- a/hotspot/src/share/vm/runtime/thread.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/runtime/thread.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -2583,6 +2583,12 @@
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());
}
}
--- a/hotspot/src/share/vm/utilities/ostream.cpp Fri Oct 05 13:37:08 2012 -0700
+++ b/hotspot/src/share/vm/utilities/ostream.cpp Fri Oct 05 18:57:10 2012 -0700
@@ -759,7 +759,7 @@
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;
}