Mercurial > hg > graal-compiler
changeset 4872:aa3d708d67c4
7141200: log some interesting information in ring buffers for crashes
Reviewed-by: kvn, jrose, kevinw, brutisso, twisti, jmasa
line wrap: on
line diff
--- a/src/os/windows/vm/os_windows.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/os/windows/vm/os_windows.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -2088,7 +2088,6 @@ #elif _M_AMD64 PCONTEXT ctx = exceptionInfo->ContextRecord; address pc = (address)ctx->Rip; - NOT_PRODUCT(Events::log("idiv overflow exception at " INTPTR_FORMAT , pc)); assert(pc[0] == 0xF7, "not an idiv opcode"); assert((pc[1] & ~0x7) == 0xF8, "cannot handle non-register operands"); assert(ctx->Rax == min_jint, "unexpected idiv exception"); @@ -2100,7 +2099,6 @@ #else PCONTEXT ctx = exceptionInfo->ContextRecord; address pc = (address)ctx->Eip; - NOT_PRODUCT(Events::log("idiv overflow exception at " INTPTR_FORMAT , pc)); assert(pc[0] == 0xF7, "not an idiv opcode"); assert((pc[1] & ~0x7) == 0xF8, "cannot handle non-register operands"); assert(ctx->Eax == min_jint, "unexpected idiv exception"); @@ -5331,4 +5329,3 @@ } #endif -
--- a/src/share/vm/c1/c1_Runtime1.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/c1/c1_Runtime1.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1999, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -597,7 +597,6 @@ JRT_ENTRY(void, Runtime1::throw_range_check_exception(JavaThread* thread, int index)) NOT_PRODUCT(_throw_range_check_exception_count++;) - Events::log("throw_range_check"); char message[jintAsStringSize]; sprintf(message, "%d", index); SharedRuntime::throw_and_post_jvmti_exception(thread, vmSymbols::java_lang_ArrayIndexOutOfBoundsException(), message); @@ -606,7 +605,6 @@ JRT_ENTRY(void, Runtime1::throw_index_exception(JavaThread* thread, int index)) NOT_PRODUCT(_throw_index_exception_count++;) - Events::log("throw_index"); char message[16]; sprintf(message, "%d", index); SharedRuntime::throw_and_post_jvmti_exception(thread, vmSymbols::java_lang_IndexOutOfBoundsException(), message); @@ -804,11 +802,7 @@ // Note also that in the presence of inlining it is not guaranteed // that caller_method() == caller_code->method() - int bci = vfst.bci(); - - Events::log("patch_code @ " INTPTR_FORMAT , caller_frame.pc()); - Bytecodes::Code code = caller_method()->java_code_at(bci); #ifndef PRODUCT
--- a/src/share/vm/ci/ciEnv.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/ci/ciEnv.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1999, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -284,6 +284,20 @@ // Return state of appropriate compilability int compilable() { return _compilable; } + const char* retry_message() const { + switch (_compilable) { + case ciEnv::MethodCompilable_not_at_tier: + return "retry at different tier"; + case ciEnv::MethodCompilable_never: + return "not retryable"; + case ciEnv::MethodCompilable: + return NULL; + default: + ShouldNotReachHere(); + return NULL; + } + } + bool break_at_compile() { return _break_at_compile; } void set_break_at_compile(bool z) { _break_at_compile = z; }
--- a/src/share/vm/code/compiledIC.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/code/compiledIC.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -165,7 +165,6 @@ instruction_address(), method->print_value_string(), entry); } - Events::log("compiledIC " INTPTR_FORMAT " --> megamorphic " INTPTR_FORMAT, this, (address)method()); // We can't check this anymore. With lazy deopt we could have already // cleaned this IC entry before we even return. This is possible if // we ran out of space in the inline cache buffer trying to do the
--- a/src/share/vm/code/nmethod.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/code/nmethod.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -704,7 +704,6 @@ xtty->tail("print_native_nmethod"); } } - Events::log("Create nmethod " INTPTR_FORMAT, this); } // For dtrace wrappers @@ -781,7 +780,6 @@ xtty->tail("print_dtrace_nmethod"); } } - Events::log("Create nmethod " INTPTR_FORMAT, this); } #endif // def HAVE_DTRACE_H @@ -889,13 +887,6 @@ if (printnmethods || PrintDebugInfo || PrintRelocations || PrintDependencies || PrintExceptionHandlers) { print_nmethod(printnmethods); } - - // Note: Do not verify in here as the CodeCache_lock is - // taken which would conflict with the CompiledIC_lock - // which taken during the verification of call sites. - // (was bug - gri 10/25/99) - - Events::log("Create nmethod " INTPTR_FORMAT, this); } @@ -1386,7 +1377,7 @@ assert_locked_or_safepoint(CodeCache_lock); // completely deallocate this method - EventMark m("flushing nmethod " INTPTR_FORMAT " %s", this, ""); + Events::log(JavaThread::current(), "flushing nmethod " INTPTR_FORMAT, this); if (PrintMethodFlushing) { tty->print_cr("*flushing nmethod %3d/" INTPTR_FORMAT ". Live blobs:" UINT32_FORMAT "/Free CodeCache:" SIZE_FORMAT "Kb", _compile_id, this, CodeCache::nof_blobs(), CodeCache::unallocated_capacity()/1024);
--- a/src/share/vm/compiler/compileBroker.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/compiler/compileBroker.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1999, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -44,6 +44,7 @@ #include "runtime/sharedRuntime.hpp" #include "runtime/sweeper.hpp" #include "utilities/dtrace.hpp" +#include "utilities/events.hpp" #ifdef COMPILER1 #include "c1/c1_Compiler.hpp" #endif @@ -189,6 +190,43 @@ GrowableArray<CompilerThread*>* CompileBroker::_method_threads = NULL; +class CompilationLog : public StringEventLog { + public: + CompilationLog() : StringEventLog("Compilation events") { + } + + void log_compile(JavaThread* thread, CompileTask* task) { + StringLogMessage lm; + stringStream msg = lm.stream(); + // msg.time_stamp().update_to(tty->time_stamp().ticks()); + task->print_compilation(&msg, true); + log(thread, "%s", (const char*)lm); + } + + void log_nmethod(JavaThread* thread, nmethod* nm) { + log(thread, "nmethod " INTPTR_FORMAT " code ["INTPTR_FORMAT ", " INTPTR_FORMAT "]", + nm, nm->code_begin(), nm->code_end()); + } + + void log_failure(JavaThread* thread, CompileTask* task, const char* reason, const char* retry_message) { + StringLogMessage lm; + lm.print("%4d COMPILE SKIPPED: %s", task->compile_id(), reason); + if (retry_message != NULL) { + lm.append(" (%s)", retry_message); + } + lm.print("\n"); + log(thread, "%s", (const char*)lm); + } +}; + +static CompilationLog* _compilation_log = NULL; + +void compileBroker_init() { + if (LogEvents) { + _compilation_log = new CompilationLog(); + } +} + CompileTaskWrapper::CompileTaskWrapper(CompileTask* task) { CompilerThread* thread = CompilerThread::current(); thread->set_task(task); @@ -326,8 +364,12 @@ // ------------------------------------------------------------------ // CompileTask::print_compilation_impl -void CompileTask::print_compilation_impl(outputStream* st, methodOop method, int compile_id, int comp_level, bool is_osr_method, int osr_bci, bool is_blocking, const char* msg) { - st->print("%7d ", (int) st->time_stamp().milliseconds()); // print timestamp +void CompileTask::print_compilation_impl(outputStream* st, methodOop method, int compile_id, int comp_level, + bool is_osr_method, int osr_bci, bool is_blocking, + const char* msg, bool short_form) { + if (!short_form) { + st->print("%7d ", (int) st->time_stamp().milliseconds()); // print timestamp + } st->print("%4d ", compile_id); // print compilation number // For unloaded methods the transition to zombie occurs after the @@ -370,7 +412,9 @@ if (msg != NULL) { st->print(" %s", msg); } - st->cr(); + if (!short_form) { + st->cr(); + } } // ------------------------------------------------------------------ @@ -426,12 +470,12 @@ // ------------------------------------------------------------------ // CompileTask::print_compilation -void CompileTask::print_compilation(outputStream* st) { +void CompileTask::print_compilation(outputStream* st, bool short_form) { oop rem = JNIHandles::resolve(method_handle()); assert(rem != NULL && rem->is_method(), "must be"); methodOop method = (methodOop) rem; bool is_osr_method = osr_bci() != InvocationEntryBci; - print_compilation_impl(st, method, compile_id(), comp_level(), is_osr_method, osr_bci(), is_blocking()); + print_compilation_impl(st, method, compile_id(), comp_level(), is_osr_method, osr_bci(), is_blocking(), NULL, short_form); } // ------------------------------------------------------------------ @@ -1648,6 +1692,10 @@ CompilerThread* thread = CompilerThread::current(); ResourceMark rm(thread); + if (LogEvents) { + _compilation_log->log_compile(thread, task); + } + // Common flags. uint compile_id = task->compile_id(); int osr_bci = task->osr_bci(); @@ -1716,22 +1764,30 @@ ci_env.record_method_not_compilable("compile failed", !TieredCompilation); } + // Copy this bit to the enclosing block: + compilable = ci_env.compilable(); + if (ci_env.failing()) { - // Copy this bit to the enclosing block: - compilable = ci_env.compilable(); + const char* retry_message = ci_env.retry_message(); + if (_compilation_log != NULL) { + _compilation_log->log_failure(thread, task, ci_env.failure_reason(), retry_message); + } if (PrintCompilation) { - const char* reason = ci_env.failure_reason(); - if (compilable == ciEnv::MethodCompilable_not_at_tier) { - tty->print_cr("%4d COMPILE SKIPPED: %s (retry at different tier)", compile_id, reason); - } else if (compilable == ciEnv::MethodCompilable_never) { - tty->print_cr("%4d COMPILE SKIPPED: %s (not retryable)", compile_id, reason); - } else if (compilable == ciEnv::MethodCompilable) { - tty->print_cr("%4d COMPILE SKIPPED: %s", compile_id, reason); + tty->print("%4d COMPILE SKIPPED: %s", compile_id, ci_env.failure_reason()); + if (retry_message != NULL) { + tty->print(" (%s)", retry_message); } + tty->cr(); } } else { task->mark_success(); task->set_num_inlined_bytecodes(ci_env.num_inlined_bytecodes()); + if (_compilation_log != NULL) { + nmethod* code = task->code(); + if (code != NULL) { + _compilation_log->log_nmethod(thread, code); + } + } } } pop_jni_handle_block();
--- a/src/share/vm/compiler/compileBroker.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/compiler/compileBroker.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1999, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1999, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -98,12 +98,16 @@ void set_prev(CompileTask* prev) { _prev = prev; } private: - static void print_compilation_impl(outputStream* st, methodOop method, int compile_id, int comp_level, bool is_osr_method = false, int osr_bci = -1, bool is_blocking = false, const char* msg = NULL); + static void print_compilation_impl(outputStream* st, methodOop method, int compile_id, int comp_level, + bool is_osr_method = false, int osr_bci = -1, bool is_blocking = false, + const char* msg = NULL, bool short_form = false); public: - void print_compilation(outputStream* st = tty); + void print_compilation(outputStream* st = tty, bool short_form = false); static void print_compilation(outputStream* st, const nmethod* nm, const char* msg = NULL) { - print_compilation_impl(st, nm->method(), nm->compile_id(), nm->comp_level(), nm->is_osr_method(), nm->is_osr_method() ? nm->osr_entry_bci() : -1, /*is_blocking*/ false, msg); + print_compilation_impl(st, nm->method(), nm->compile_id(), nm->comp_level(), + nm->is_osr_method(), nm->is_osr_method() ? nm->osr_entry_bci() : -1, /*is_blocking*/ false, + msg); } static void print_inlining(outputStream* st, ciMethod* method, int inline_level, int bci, const char* msg = NULL);
--- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1228,9 +1228,7 @@ SvcGCMarker sgcm(SvcGCMarker::FULL); ResourceMark rm; - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - } + print_heap_before_gc(); HRSPhaseSetter x(HRSPhaseFullGC); verify_region_sets_optional(); @@ -1470,9 +1468,7 @@ _hrs.verify_optional(); verify_region_sets_optional(); - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + print_heap_after_gc(); g1mm()->update_sizes(); post_full_gc_dump(); @@ -3537,9 +3533,7 @@ SvcGCMarker sgcm(SvcGCMarker::MINOR); ResourceMark rm; - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - } + print_heap_before_gc(); HRSPhaseSetter x(HRSPhaseEvacuation); verify_region_sets_optional(); @@ -3890,9 +3884,7 @@ TASKQUEUE_STATS_ONLY(if (ParallelGCVerbose) print_taskqueue_stats()); TASKQUEUE_STATS_ONLY(reset_taskqueue_stats()); - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + print_heap_after_gc(); g1mm()->update_sizes(); if (G1SummarizeRSetStats &&
--- a/src/share/vm/gc_implementation/g1/g1MarkSweep.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_implementation/g1/g1MarkSweep.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -126,7 +126,6 @@ void G1MarkSweep::mark_sweep_phase1(bool& marked_for_unloading, bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - EventMark m("1 mark object"); TraceTime tm("phase 1", PrintGC && Verbose, true, gclog_or_tty); GenMarkSweep::trace(" 1"); @@ -292,7 +291,6 @@ G1CollectedHeap* g1h = G1CollectedHeap::heap(); Generation* pg = g1h->perm_gen(); - EventMark m("2 compute new addresses"); TraceTime tm("phase 2", PrintGC && Verbose, true, gclog_or_tty); GenMarkSweep::trace("2"); @@ -337,7 +335,6 @@ Generation* pg = g1h->perm_gen(); // Adjust the pointers to reflect the new locations - EventMark m("3 adjust pointers"); TraceTime tm("phase 3", PrintGC && Verbose, true, gclog_or_tty); GenMarkSweep::trace("3"); @@ -402,7 +399,6 @@ G1CollectedHeap* g1h = G1CollectedHeap::heap(); Generation* pg = g1h->perm_gen(); - EventMark m("4 compact heap"); TraceTime tm("phase 4", PrintGC && Verbose, true, gclog_or_tty); GenMarkSweep::trace("4");
--- a/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_implementation/parallelScavenge/psMarkSweep.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -132,9 +132,7 @@ AdaptiveSizePolicyOutput(size_policy, heap->total_collections()); - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - } + heap->print_heap_before_gc(); // Fill in TLABs heap->accumulate_statistics_all_tlabs(); @@ -377,9 +375,7 @@ NOT_PRODUCT(ref_processor()->verify_no_references_recorded()); - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + heap->print_heap_after_gc(); heap->post_full_gc_dump(); @@ -504,7 +500,6 @@ void PSMarkSweep::mark_sweep_phase1(bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - EventMark m("1 mark object"); TraceTime tm("phase 1", PrintGCDetails && Verbose, true, gclog_or_tty); trace(" 1"); @@ -563,7 +558,6 @@ void PSMarkSweep::mark_sweep_phase2() { - EventMark m("2 compute new addresses"); TraceTime tm("phase 2", PrintGCDetails && Verbose, true, gclog_or_tty); trace("2"); @@ -608,7 +602,6 @@ void PSMarkSweep::mark_sweep_phase3() { // Adjust the pointers to reflect the new locations - EventMark m("3 adjust pointers"); TraceTime tm("phase 3", PrintGCDetails && Verbose, true, gclog_or_tty); trace("3");
--- a/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_implementation/parallelScavenge/psParallelCompact.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2005, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2005, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -983,9 +983,7 @@ // We need to track unique mark sweep invocations as well. _total_invocations++; - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - } + heap->print_heap_before_gc(); // Fill in TLABs heap->accumulate_statistics_all_tlabs(); @@ -1838,7 +1836,6 @@ void PSParallelCompact::summary_phase(ParCompactionManager* cm, bool maximum_compaction) { - EventMark m("2 summarize"); TraceTime tm("summary phase", print_phases(), true, gclog_or_tty); // trace("2"); @@ -2237,9 +2234,7 @@ collection_exit.update(); - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + heap->print_heap_after_gc(); if (PrintGCTaskTimeStamps) { gclog_or_tty->print_cr("VM-Thread " INT64_FORMAT " " INT64_FORMAT " " INT64_FORMAT, @@ -2352,7 +2347,6 @@ void PSParallelCompact::marking_phase(ParCompactionManager* cm, bool maximum_heap_compaction) { // Recursively traverse all live objects and mark them - EventMark m("1 mark object"); TraceTime tm("marking phase", print_phases(), true, gclog_or_tty); ParallelScavengeHeap* heap = gc_heap(); @@ -2438,7 +2432,6 @@ void PSParallelCompact::adjust_roots() { // Adjust the pointers to reflect the new locations - EventMark m("3 adjust roots"); TraceTime tm("adjust roots", print_phases(), true, gclog_or_tty); // General strong roots. @@ -2469,7 +2462,6 @@ } void PSParallelCompact::compact_perm(ParCompactionManager* cm) { - EventMark m("4 compact perm"); TraceTime tm("compact perm gen", print_phases(), true, gclog_or_tty); // trace("4"); @@ -2647,7 +2639,6 @@ } void PSParallelCompact::compact() { - EventMark m("5 compact"); // trace("5"); TraceTime tm("compaction phase", print_phases(), true, gclog_or_tty); @@ -3502,4 +3493,3 @@ _updated_int_array_klass_obj = (klassOop) summary_data().calc_new_pointer(Universe::intArrayKlassObj()); } -
--- a/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_implementation/parallelScavenge/psScavenge.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2002, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2002, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -295,9 +295,7 @@ heap->record_gen_tops_before_GC(); } - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - } + heap->print_heap_before_gc(); assert(!NeverTenure || _tenuring_threshold == markOopDesc::max_age + 1, "Sanity"); assert(!AlwaysTenure || _tenuring_threshold == 0, "Sanity"); @@ -643,9 +641,7 @@ Universe::verify(false); } - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + heap->print_heap_after_gc(); if (ZapUnusedHeapArea) { young_gen->eden_space()->check_mangled_unused_area_complete();
--- a/src/share/vm/gc_interface/collectedHeap.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_interface/collectedHeap.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -51,6 +51,31 @@ size_t CollectedHeap::_filler_array_max_size = 0; +template <> +void EventLogBase<GCMessage>::print(outputStream* st, GCMessage& m) { + st->print_cr("GC heap %s", m.is_before ? "before" : "after"); + st->print_raw(m); +} + +void GCHeapLog::log_heap(bool before) { + if (!should_log()) { + return; + } + + jlong timestamp = os::javaTimeNanos() / NANOSECS_PER_MILLISEC; + MutexLockerEx ml(&_mutex, Mutex::_no_safepoint_check_flag); + int index = compute_log_index(); + _records[index].thread = NULL; // Its the GC thread so it's not that interesting. + _records[index].timestamp = timestamp; + _records[index].data.is_before = before; + stringStream st(_records[index].data.buffer(), _records[index].data.size()); + if (before) { + Universe::print_heap_before_gc(&st); + } else { + Universe::print_heap_after_gc(&st); + } +} + // Memory state functions. @@ -81,6 +106,12 @@ 80, GCCause::to_string(_gc_lastcause), CHECK); } _defer_initial_card_mark = false; // strengthened by subclass in pre_initialize() below. + // Create the ring log + if (LogEvents) { + _gc_heap_log = new GCHeapLog(); + } else { + _gc_heap_log = NULL; + } } void CollectedHeap::pre_initialize() {
--- a/src/share/vm/gc_interface/collectedHeap.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/gc_interface/collectedHeap.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -31,6 +31,7 @@ #include "runtime/handles.hpp" #include "runtime/perfData.hpp" #include "runtime/safepoint.hpp" +#include "utilities/events.hpp" // A "CollectedHeap" is an implementation of a java heap for HotSpot. This // is an abstract class: there may be many different kinds of heaps. This @@ -43,6 +44,29 @@ class Thread; class CollectorPolicy; +class GCMessage : public FormatBuffer<1024> { + public: + bool is_before; + + public: + GCMessage() {} +}; + +class GCHeapLog : public EventLogBase<GCMessage> { + private: + void log_heap(bool before); + + public: + GCHeapLog() : EventLogBase<GCMessage>("GC Heap History") {} + + void log_heap_before() { + log_heap(true); + } + void log_heap_after() { + log_heap(false); + } +}; + // // CollectedHeap // SharedHeap @@ -62,6 +86,8 @@ // Used for filler objects (static, but initialized in ctor). static size_t _filler_array_max_size; + GCHeapLog* _gc_heap_log; + // Used in support of ReduceInitialCardMarks; only consulted if COMPILER2 is being used bool _defer_initial_card_mark; @@ -618,6 +644,27 @@ // Default implementation does nothing. virtual void print_tracing_info() const = 0; + // If PrintHeapAtGC is set call the appropriate routi + void print_heap_before_gc() { + if (PrintHeapAtGC) { + Universe::print_heap_before_gc(); + } + if (_gc_heap_log != NULL) { + _gc_heap_log->log_heap_before(); + } + } + void print_heap_after_gc() { + if (PrintHeapAtGC) { + Universe::print_heap_after_gc(); + } + if (_gc_heap_log != NULL) { + _gc_heap_log->log_heap_after(); + } + } + + // Allocate GCHeapLog during VM startup + static void initialize_heap_log(); + // Heap verification virtual void verify(bool allow_dirty, bool silent, VerifyOption option) = 0;
--- a/src/share/vm/memory/genCollectedHeap.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/memory/genCollectedHeap.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -479,11 +479,9 @@ const size_t perm_prev_used = perm_gen()->used(); - if (PrintHeapAtGC) { - Universe::print_heap_before_gc(); - if (Verbose) { - gclog_or_tty->print_cr("GC Cause: %s", GCCause::to_string(gc_cause())); - } + print_heap_before_gc(); + if (Verbose) { + gclog_or_tty->print_cr("GC Cause: %s", GCCause::to_string(gc_cause())); } { @@ -685,9 +683,7 @@ AdaptiveSizePolicy* sp = gen_policy()->size_policy(); AdaptiveSizePolicyOutput(sp, total_collections()); - if (PrintHeapAtGC) { - Universe::print_heap_after_gc(); - } + print_heap_after_gc(); #ifdef TRACESPINNING ParallelTaskTerminator::print_termination_counts();
--- a/src/share/vm/memory/genMarkSweep.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/memory/genMarkSweep.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2001, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -254,7 +254,6 @@ void GenMarkSweep::mark_sweep_phase1(int level, bool clear_all_softrefs) { // Recursively traverse all live objects and mark them - EventMark m("1 mark object"); TraceTime tm("phase 1", PrintGC && Verbose, true, gclog_or_tty); trace(" 1"); @@ -325,7 +324,6 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); Generation* pg = gch->perm_gen(); - EventMark m("2 compute new addresses"); TraceTime tm("phase 2", PrintGC && Verbose, true, gclog_or_tty); trace("2"); @@ -350,7 +348,6 @@ Generation* pg = gch->perm_gen(); // Adjust the pointers to reflect the new locations - EventMark m("3 adjust pointers"); TraceTime tm("phase 3", PrintGC && Verbose, true, gclog_or_tty); trace("3"); @@ -411,7 +408,6 @@ GenCollectedHeap* gch = GenCollectedHeap::heap(); Generation* pg = gch->perm_gen(); - EventMark m("4 compact heap"); TraceTime tm("phase 4", PrintGC && Verbose, true, gclog_or_tty); trace("4");
--- a/src/share/vm/prims/jvm.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/prims/jvm.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -2716,7 +2716,9 @@ } oop java_thread = JNIHandles::resolve_non_null(jthread); JavaThread* receiver = java_lang_Thread::thread(java_thread); - Events::log("JVM_StopThread thread JavaThread " INTPTR_FORMAT " as oop " INTPTR_FORMAT " [exception " INTPTR_FORMAT "]", receiver, (address)java_thread, throwable); + Events::log_exception(JavaThread::current(), + "JVM_StopThread thread JavaThread " INTPTR_FORMAT " as oop " INTPTR_FORMAT " [exception " INTPTR_FORMAT "]", + receiver, (address)java_thread, throwable); // First check if thread is alive if (receiver != NULL) { // Check if exception is getting thrown at self (use oop equality, since the
--- a/src/share/vm/runtime/deoptimization.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/deoptimization.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -339,7 +339,6 @@ #ifdef ASSERT assert(cb->is_deoptimization_stub() || cb->is_uncommon_trap_stub(), "just checking"); - Events::log("fetch unroll sp " INTPTR_FORMAT, unpack_sp); #endif #else intptr_t* unpack_sp = stub_frame.sender(&dummy_map).unextended_sp(); @@ -577,6 +576,8 @@ tty->print_cr("DEOPT UNPACKING thread " INTPTR_FORMAT " vframeArray " INTPTR_FORMAT " mode %d", thread, array, exec_mode); } #endif + Events::log(thread, "DEOPT UNPACKING pc=" INTPTR_FORMAT " sp=" INTPTR_FORMAT " mode %d", + stub_frame.pc(), stub_frame.sp(), exec_mode); UnrollBlock* info = array->unroll_block(); @@ -981,6 +982,7 @@ #endif // COMPILER2 vframeArray* Deoptimization::create_vframeArray(JavaThread* thread, frame fr, RegisterMap *reg_map, GrowableArray<compiledVFrame*>* chunk) { + Events::log(thread, "DEOPT PACKING pc=" INTPTR_FORMAT " sp=" INTPTR_FORMAT, fr.pc(), fr.sp()); #ifndef PRODUCT if (TraceDeoptimization) { @@ -1026,7 +1028,6 @@ // Compare the vframeArray to the collected vframes assert(array->structural_compare(thread, chunk), "just checking"); - Events::log("# vframes = %d", (intptr_t)chunk->length()); #ifndef PRODUCT if (TraceDeoptimization) { @@ -1124,8 +1125,6 @@ gather_statistics(Reason_constraint, Action_none, Bytecodes::_illegal); - EventMark m("Deoptimization (pc=" INTPTR_FORMAT ", sp=" INTPTR_FORMAT ")", fr.pc(), fr.id()); - // Patch the nmethod so that when execution returns to it we will // deopt the execution state and return to the interpreter. fr.deoptimize(thread); @@ -1239,6 +1238,10 @@ // before we are done with it. nmethodLocker nl(fr.pc()); + // Log a message + Events::log_deopt_message(thread, "Uncommon trap %d fr.pc " INTPTR_FORMAT, + trap_request, fr.pc()); + { ResourceMark rm; @@ -1249,7 +1252,6 @@ DeoptAction action = trap_request_action(trap_request); jint unloaded_class_index = trap_request_index(trap_request); // CP idx or -1 - Events::log("Uncommon trap occurred @" INTPTR_FORMAT " unloaded_class_index = %d", fr.pc(), (int) trap_request); vframe* vf = vframe::new_vframe(&fr, ®_map, thread); compiledVFrame* cvf = compiledVFrame::cast(vf);
--- a/src/share/vm/runtime/frame.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/frame.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -570,7 +570,7 @@ InterpreterCodelet* desc = Interpreter::codelet_containing(pc()); if (desc != NULL) { st->print("~"); - desc->print(); + desc->print_on(st); NOT_PRODUCT(begin = desc->code_begin(); end = desc->code_end();) } else { st->print("~interpreter");
--- a/src/share/vm/runtime/globals.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/globals.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -736,8 +736,11 @@ product(bool, MaxFDLimit, true, \ "Bump the number of file descriptors to max in solaris.") \ \ - notproduct(bool, LogEvents, trueInDebug, \ - "Enable Event log") \ + diagnostic(bool, LogEvents, true, \ + "Enable the various ring buffer event logs") \ + \ + diagnostic(intx, LogEventsBufferEntries, 10, \ + "Enable the various ring buffer event logs") \ \ product(bool, BytecodeVerificationRemote, true, \ "Enables the Java bytecode verifier for remote classes") \
--- a/src/share/vm/runtime/init.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/init.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -65,7 +65,7 @@ void InlineCacheBuffer_init(); void compilerOracle_init(); void compilationPolicy_init(); - +void compileBroker_init(); // Initialization after compiler initialization bool universe_post_init(); // must happen after compiler_init @@ -120,6 +120,7 @@ InlineCacheBuffer_init(); compilerOracle_init(); compilationPolicy_init(); + compileBroker_init(); VMRegImpl::set_regName(); if (!universe_post_init()) {
--- a/src/share/vm/runtime/mutex.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/mutex.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,6 +1,6 @@ /* - * Copyright (c) 1998, 2010, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1998, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -1296,10 +1296,6 @@ assert(this->rank() >= 0, "bad lock rank"); - if (LogMultipleMutexLocking && locks != NULL) { - Events::log("thread " INTPTR_FORMAT " locks %s, already owns %s", new_owner, name(), locks->name()); - } - // Deadlock avoidance rules require us to acquire Mutexes only in // a global total order. For example m1 is the lowest ranked mutex // that the thread holds and m2 is the mutex the thread is trying @@ -1343,10 +1339,6 @@ #ifdef ASSERT Monitor *locks = old_owner->owned_locks(); - if (LogMultipleMutexLocking && locks != this) { - Events::log("thread " INTPTR_FORMAT " unlocks %s, still owns %s", old_owner, this->name(), locks->name()); - } - // remove "this" from the owned locks list Monitor *prev = NULL;
--- a/src/share/vm/runtime/sharedRuntime.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/sharedRuntime.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -886,9 +886,9 @@ // for AbortVMOnException flag NOT_PRODUCT(Exceptions::debug_check_abort("java.lang.NullPointerException")); if (exception_kind == IMPLICIT_NULL) { - Events::log("Implicit null exception at " INTPTR_FORMAT " to " INTPTR_FORMAT, pc, target_pc); + Events::log_exception(thread, "Implicit null exception at " INTPTR_FORMAT " to " INTPTR_FORMAT, pc, target_pc); } else { - Events::log("Implicit division by zero exception at " INTPTR_FORMAT " to " INTPTR_FORMAT, pc, target_pc); + Events::log_exception(thread, "Implicit division by zero exception at " INTPTR_FORMAT " to " INTPTR_FORMAT, pc, target_pc); } return target_pc; } @@ -1541,7 +1541,6 @@ if (caller.is_compiled_frame() && !caller.is_deoptimized_frame()) { address pc = caller.pc(); - Events::log("update call-site at pc " INTPTR_FORMAT, pc); // Default call_addr is the location of the "basic" call. // Determine the address of the call we a reresolving. With
--- a/src/share/vm/runtime/thread.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/runtime/thread.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -1600,8 +1600,6 @@ // java.lang.Thread.dispatchUncaughtException if (uncaught_exception.not_null()) { Handle group(this, java_lang_Thread::threadGroup(threadObj())); - Events::log("uncaught exception INTPTR_FORMAT " " INTPTR_FORMAT " " INTPTR_FORMAT", - (address)uncaught_exception(), (address)threadObj(), (address)group()); { EXCEPTION_MARK; // Check if the method Thread.dispatchUncaughtException() exists. If so @@ -3885,7 +3883,7 @@ ThreadService::add_thread(p, daemon); // Possible GC point. - Events::log("Thread added: " INTPTR_FORMAT, p); + Events::log(p, "Thread added: " INTPTR_FORMAT, p); } void Threads::remove(JavaThread* p) { @@ -3930,7 +3928,7 @@ } // unlock Threads_lock // Since Events::log uses a lock, we grab it outside the Threads_lock - Events::log("Thread exited: " INTPTR_FORMAT, p); + Events::log(p, "Thread exited: " INTPTR_FORMAT, p); } // Threads_lock must be held when this is called (or must be called during a safepoint)
--- a/src/share/vm/utilities/debug.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/debug.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -601,18 +601,6 @@ } -extern "C" void events() { - Command c("events"); - Events::print_last(tty, 50); -} - - -extern "C" void nevents(int n) { - Command c("events"); - Events::print_last(tty, n); -} - - // Given a heap address that was valid before the most recent GC, if // the oop that used to contain it is still live, prints the new // location of the oop and the address. Useful for tracking down
--- a/src/share/vm/utilities/debug.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/debug.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -33,16 +33,23 @@ // Simple class to format the ctor arguments into a fixed-sized buffer. template <size_t bufsz = 256> class FormatBuffer { -public: + public: inline FormatBuffer(const char * format, ...); inline void append(const char* format, ...); + inline void print(const char* format, ...); + inline void printv(const char* format, va_list ap); operator const char *() const { return _buf; } -private: + char* buffer() { return _buf; } + int size() { return bufsz; } + + private: FormatBuffer(const FormatBuffer &); // prevent copies -private: + protected: char _buf[bufsz]; + + inline FormatBuffer(); }; template <size_t bufsz> @@ -54,6 +61,24 @@ } template <size_t bufsz> +FormatBuffer<bufsz>::FormatBuffer() { + _buf[0] = '\0'; +} + +template <size_t bufsz> +void FormatBuffer<bufsz>::print(const char * format, ...) { + va_list argp; + va_start(argp, format); + jio_vsnprintf(_buf, bufsz, format, argp); + va_end(argp); +} + +template <size_t bufsz> +void FormatBuffer<bufsz>::printv(const char * format, va_list argp) { + jio_vsnprintf(_buf, bufsz, format, argp); +} + +template <size_t bufsz> void FormatBuffer<bufsz>::append(const char* format, ...) { // Given that the constructor does a vsnprintf we can assume that // _buf is already initialized.
--- a/src/share/vm/utilities/events.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/events.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2010, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -26,6 +26,7 @@ #include "memory/allocation.inline.hpp" #include "runtime/mutexLocker.hpp" #include "runtime/osThread.hpp" +#include "runtime/threadCritical.hpp" #include "runtime/threadLocalStorage.hpp" #include "runtime/timer.hpp" #include "utilities/events.hpp" @@ -43,184 +44,40 @@ #endif -#ifndef PRODUCT - -//////////////////////////////////////////////////////////////////////////// -// Event - -typedef u4 EventID; - -class Event VALUE_OBJ_CLASS_SPEC { - private: - jlong _time_tick; - intx _thread_id; - const char* _format; - int _indent; - intptr_t _arg_1; - intptr_t _arg_2; - intptr_t _arg_3; - - // only EventBuffer::add_event() can assign event id - friend class EventBuffer; - EventID _id; - - public: - - void clear() { _format = NULL; } - - EventID id() const { return _id; } - - void fill(int indent, const char* format, intptr_t arg_1, intptr_t arg_2, intptr_t arg_3) { - _format = format; - _arg_1 = arg_1; - _arg_2 = arg_2; - _arg_3 = arg_3; - - _indent = indent; - - _thread_id = os::current_thread_id(); - _time_tick = os::elapsed_counter(); - } - - void print_on(outputStream *st) { - if (_format == NULL) return; - st->print(" %d", _thread_id); - st->print(" %3.2g ", (double)_time_tick / os::elapsed_frequency()); - st->fill_to(20); - for (int index = 0; index < _indent; index++) { - st->print("| "); - } - st->print_cr(_format, _arg_1, _arg_2, _arg_3); - } -}; - -//////////////////////////////////////////////////////////////////////////// -// EventBuffer -// -// Simple lock-free event queue. Every event has a unique 32-bit id. -// It's fine if two threads add events at the same time, because they -// will get different event id, and then write to different buffer location. -// However, it is assumed that add_event() is quick enough (or buffer size -// is big enough), so when one thread is adding event, there can't be more -// than "size" events created by other threads; otherwise we'll end up having -// two threads writing to the same location. - -class EventBuffer : AllStatic { - private: - static Event* buffer; - static int size; - static jint indent; - static volatile EventID _current_event_id; - - static EventID get_next_event_id() { - return (EventID)Atomic::add(1, (jint*)&_current_event_id); - } - - public: - static void inc_indent() { Atomic::inc(&indent); } - static void dec_indent() { Atomic::dec(&indent); } +EventLog* Events::_logs = NULL; +StringEventLog* Events::_messages = NULL; +StringEventLog* Events::_exceptions = NULL; +StringEventLog* Events::_deopt_messages = NULL; - static bool get_event(EventID id, Event* event) { - int index = (int)(id % size); - if (buffer[index].id() == id) { - memcpy(event, &buffer[index], sizeof(Event)); - // check id again; if buffer[index] is being updated by another thread, - // event->id() will contain different value. - return (event->id() == id); - } else { - // id does not match - id is invalid, or event is overwritten - return false; - } - } - - // add a new event to the queue; if EventBuffer is full, this call will - // overwrite the oldest event in the queue - static EventID add_event(const char* format, - intptr_t arg_1, intptr_t arg_2, intptr_t arg_3) { - // assign a unique id - EventID id = get_next_event_id(); - - // event will be copied to buffer[index] - int index = (int)(id % size); - - // first, invalidate id, buffer[index] can't have event with id = index + 2 - buffer[index]._id = index + 2; - - // make sure everyone has seen that buffer[index] is invalid - OrderAccess::fence(); - - // ... before updating its value - buffer[index].fill(indent, format, arg_1, arg_2, arg_3); - - // finally, set up real event id, now buffer[index] contains valid event - OrderAccess::release_store(&(buffer[index]._id), id); - - return id; - } - - static void print_last(outputStream *st, int number) { - st->print_cr("[Last %d events in the event buffer]", number); - st->print_cr("-<thd>-<elapsed sec>-<description>---------------------"); +EventLog::EventLog() { + // This normally done during bootstrap when we're only single + // threaded but use a ThreadCritical to ensure inclusion in case + // some are created slightly late. + ThreadCritical tc; + _next = Events::_logs; + Events::_logs = this; +} - int count = 0; - EventID id = _current_event_id; - while (count < number) { - Event event; - if (get_event(id, &event)) { - event.print_on(st); - } - id--; - count++; - } - } - - static void print_all(outputStream* st) { - print_last(st, size); - } - - static void init() { - // Allocate the event buffer - size = EventLogLength; - buffer = NEW_C_HEAP_ARRAY(Event, size); - - _current_event_id = 0; - - // Clear the event buffer - for (int index = 0; index < size; index++) { - buffer[index]._id = index + 1; // index + 1 is invalid id - buffer[index].clear(); - } - } -}; - -Event* EventBuffer::buffer; -int EventBuffer::size; -volatile EventID EventBuffer::_current_event_id; -int EventBuffer::indent; - -//////////////////////////////////////////////////////////////////////////// -// Events - -// Events::log() is safe for signal handlers -void Events::log(const char* format, ...) { - if (LogEvents) { - va_list ap; - va_start(ap, format); - intptr_t arg_1 = va_arg(ap, intptr_t); - intptr_t arg_2 = va_arg(ap, intptr_t); - intptr_t arg_3 = va_arg(ap, intptr_t); - va_end(ap); - - EventBuffer::add_event(format, arg_1, arg_2, arg_3); +// For each registered event logger, print out the current contents of +// the buffer. This is normally called when the JVM is crashing. +void Events::print_all(outputStream* out) { + EventLog* log = _logs; + while (log != NULL) { + log->print_log_on(out); + log = log->next(); } } -void Events::print_all(outputStream *st) { - EventBuffer::print_all(st); +void Events::init() { + if (LogEvents) { + _messages = new StringEventLog("Events"); + _exceptions = new StringEventLog("Internal exceptions"); + _deopt_messages = new StringEventLog("Deoptimization events"); + } } -void Events::print_last(outputStream *st, int number) { - EventBuffer::print_last(st, number); +void eventlog_init() { + Events::init(); } /////////////////////////////////////////////////////////////////////////// @@ -230,37 +87,17 @@ if (LogEvents) { va_list ap; va_start(ap, format); - intptr_t arg_1 = va_arg(ap, intptr_t); - intptr_t arg_2 = va_arg(ap, intptr_t); - intptr_t arg_3 = va_arg(ap, intptr_t); + // Save a copy of begin message and log it. + _buffer.printv(format, ap); + Events::log(NULL, _buffer); va_end(ap); - - EventBuffer::add_event(format, arg_1, arg_2, arg_3); - EventBuffer::inc_indent(); } } EventMark::~EventMark() { if (LogEvents) { - EventBuffer::dec_indent(); - EventBuffer::add_event("done", 0, 0, 0); + // Append " done" to the begin message and log it + _buffer.append(" done"); + Events::log(NULL, _buffer); } } - -/////////////////////////////////////////////////////////////////////////// - -void eventlog_init() { - EventBuffer::init(); -} - -int print_all_events(outputStream *st) { - EventBuffer::print_all(st); - return 1; -} - -#else - -void eventlog_init() {} -int print_all_events(outputStream *st) { return 0; } - -#endif // PRODUCT
--- a/src/share/vm/utilities/events.hpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/events.hpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2010, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -26,7 +26,10 @@ #define SHARE_VM_UTILITIES_EVENTS_HPP #include "memory/allocation.hpp" +#include "runtime/mutexLocker.hpp" +#include "runtime/thread.hpp" #include "utilities/top.hpp" +#include "utilities/vmError.hpp" // Events and EventMark provide interfaces to log events taking place in the vm. // This facility is extremly useful for post-mortem debugging. The eventlog @@ -47,26 +50,246 @@ // Max 3 arguments are saved for each logged event. // -class Events : AllStatic { +// The base event log dumping class that is registered for dumping at +// crash time. This is a very generic interface that is mainly here +// for completeness. Normally the templated EventLogBase would be +// subclassed to provide different log types. +class EventLog : public CHeapObj { + friend class Events; + + private: + EventLog* _next; + + EventLog* next() const { return _next; } + public: - // Logs an event, format as printf - static void log(const char* format, ...) PRODUCT_RETURN; + // Automatically registers the log so that it will be printed during + // crashes. + EventLog(); + + virtual void print_log_on(outputStream* out) = 0; +}; + + +// A templated subclass of EventLog that provides basic ring buffer +// functionality. Most event loggers should subclass this, possibly +// providing a more featureful log function if the existing copy +// semantics aren't appropriate. The name is used as the label of the +// log when it is dumped during a crash. +template <class T> class EventLogBase : public EventLog { + template <class X> class EventRecord { + public: + jlong timestamp; + Thread* thread; + X data; + }; + + protected: + Mutex _mutex; + const char* _name; + int _length; + int _index; + int _count; + EventRecord<T>* _records; + + public: + EventLogBase<T>(const char* name, int length = LogEventsBufferEntries): + _name(name), + _length(length), + _count(0), + _index(0), + _mutex(Mutex::event, name) { + _records = new EventRecord<T>[length]; + } - // Prints all events in the buffer - static void print_all(outputStream* st) PRODUCT_RETURN; + // move the ring buffer to next open slot and return the index of + // the slot to use for the current message. Should only be called + // while mutex is held. + int compute_log_index() { + int index = _index; + if (_count < _length) _count++; + _index++; + if (_index >= _length) _index = 0; + return index; + } + + bool should_log() { + // Don't bother adding new entries when we're crashing. This also + // avoids mutating the ring buffer when printing the log. + return !VMError::fatal_error_in_progress(); + } + + // Print the contents of the log + void print_log_on(outputStream* out); + + private: + void print_log_impl(outputStream* out); + + // Print a single element. A templated implementation might need to + // be declared by subclasses. + void print(outputStream* out, T& e); - // Prints last number events from the event buffer - static void print_last(outputStream *st, int number) PRODUCT_RETURN; + void print(outputStream* out, EventRecord<T>& e) { + out->print("Event: " INT64_FORMAT " ", e.timestamp); + if (e.thread != NULL) { + out->print("Thread " INTPTR_FORMAT " ", e.thread); + } + print(out, e.data); + } +}; + +// A simple wrapper class for fixed size text messages. +class StringLogMessage : public FormatBuffer<132> { + public: + // Wrap this buffer in a stringStream. + stringStream stream() { + return stringStream(_buf, sizeof(_buf)); + } +}; + +// A simple ring buffer of fixed size text messages. +class StringEventLog : public EventLogBase<StringLogMessage> { + public: + StringEventLog(const char* name, int count = LogEventsBufferEntries) : EventLogBase<StringLogMessage>(name, count) {} + + void logv(Thread* thread, const char* format, va_list ap) { + if (!should_log()) return; + + jlong timestamp = os::javaTimeNanos() / NANOSECS_PER_MILLISEC; + MutexLockerEx ml(&_mutex, Mutex::_no_safepoint_check_flag); + int index = compute_log_index(); + _records[index].thread = thread; + _records[index].timestamp = timestamp; + _records[index].data.printv(format, ap); + } + + void log(Thread* thread, const char* format, ...) { + va_list ap; + va_start(ap, format); + logv(thread, format, ap); + va_end(ap); + } + }; + + +class Events : AllStatic { + friend class EventLog; + + private: + static EventLog* _logs; + + // A log for generic messages that aren't well categorized. + static StringEventLog* _messages; + + // A log for internal exception related messages, like internal + // throws and implicit exceptions. + static StringEventLog* _exceptions; + + // Deoptization related messages + static StringEventLog* _deopt_messages; + + public: + static void print_all(outputStream* out); + + static void print() { + print_all(tty); + } + + // Logs a generic message with timestamp and format as printf. + static void log(Thread* thread, const char* format, ...); + + // Log exception related message + static void log_exception(Thread* thread, const char* format, ...); + + static void log_deopt_message(Thread* thread, const char* format, ...); + + // Register default loggers + static void init(); +}; + + +inline void Events::log(Thread* thread, const char* format, ...) { + if (LogEvents) { + va_list ap; + va_start(ap, format); + _messages->logv(thread, format, ap); + va_end(ap); + } +} + +inline void Events::log_exception(Thread* thread, const char* format, ...) { + if (LogEvents) { + va_list ap; + va_start(ap, format); + _exceptions->logv(thread, format, ap); + va_end(ap); + } +} + +inline void Events::log_deopt_message(Thread* thread, const char* format, ...) { + if (LogEvents) { + va_list ap; + va_start(ap, format); + _deopt_messages->logv(thread, format, ap); + va_end(ap); + } +} + + +template <class T> +inline void EventLogBase<T>::print_log_on(outputStream* out) { + if (ThreadLocalStorage::get_thread_slow() == NULL) { + // Not a regular Java thread so don't bother locking + print_log_impl(out); + } else { + MutexLockerEx ml(&_mutex, Mutex::_no_safepoint_check_flag); + print_log_impl(out); + } +} + +// Dump the ring buffer entries that current have entries. +template <class T> +inline void EventLogBase<T>::print_log_impl(outputStream* out) { + out->print_cr("%s (%d events):", _name, _count); + if (_count == 0) { + out->print_cr("No events"); + return; + } + + if (_count < _length) { + for (int i = 0; i < _count; i++) { + print(out, _records[i]); + } + } else { + for (int i = _index; i < _length; i++) { + print(out, _records[i]); + } + for (int i = 0; i < _index; i++) { + print(out, _records[i]); + } + } + out->cr(); +} + +// Implement a printing routine for the StringLogMessage +template <> +inline void EventLogBase<StringLogMessage>::print(outputStream* out, StringLogMessage& lm) { + out->print_raw(lm); + out->cr(); +} + +// Place markers for the beginning and end up of a set of events. +// These end up in the default log. class EventMark : public StackObj { + StringLogMessage _buffer; + public: // log a begin event, format as printf - EventMark(const char* format, ...) PRODUCT_RETURN; + EventMark(const char* format, ...); // log an end event - ~EventMark() PRODUCT_RETURN; + ~EventMark(); }; -int print_all_events(outputStream *st); - #endif // SHARE_VM_UTILITIES_EVENTS_HPP
--- a/src/share/vm/utilities/exceptions.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/exceptions.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1998, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1998, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -160,7 +160,7 @@ thread->set_pending_exception(h_exception(), file, line); // vm log - Events::log("throw_exception " INTPTR_FORMAT, (address)h_exception()); + Events::log_exception(thread, "Threw " INTPTR_FORMAT " at %s:%d", (address)h_exception(), file, line); }
--- a/src/share/vm/utilities/vmError.cpp Wed Feb 01 10:36:58 2012 +0100 +++ b/src/share/vm/utilities/vmError.cpp Wed Feb 01 07:59:01 2012 -0800 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2003, 2011, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2003, 2012, Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -36,6 +36,7 @@ #include "utilities/decoder.hpp" #include "utilities/defaultStream.hpp" #include "utilities/errorReporter.hpp" +#include "utilities/events.hpp" #include "utilities/top.hpp" #include "utilities/vmError.hpp" @@ -693,7 +694,14 @@ st->cr(); } - STEP(200, "(printing dynamic libraries)" ) + STEP(200, "(printing ring buffers)" ) + + if (_verbose) { + Events::print_all(st); + st->cr(); + } + + STEP(205, "(printing dynamic libraries)" ) if (_verbose) { // dynamic libraries, or memory map