--- old/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2016-02-05 08:24:07.161020908 +0100 +++ new/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp 2016-02-05 08:24:07.049020903 +0100 @@ -1517,6 +1517,8 @@ SerialOldTracer* gc_tracer = GenMarkSweep::gc_tracer(); gc_tracer->report_gc_start(gch->gc_cause(), gc_timer->gc_start()); + gch->pre_full_gc_dump(gc_timer); + GCTraceTime(Trace, gc) t("CMS:MSC"); // Temporarily widen the span of the weak reference processing to @@ -1593,6 +1595,8 @@ _inter_sweep_timer.reset(); _inter_sweep_timer.start(); + gch->post_full_gc_dump(gc_timer); + gc_timer->register_gc_end(); gc_tracer->report_gc_end(gc_timer->gc_end(), gc_timer->time_partitions()); --- old/src/share/vm/gc/parallel/psMarkSweep.cpp 2016-02-05 08:24:07.461020920 +0100 +++ new/src/share/vm/gc/parallel/psMarkSweep.cpp 2016-02-05 08:24:07.349020916 +0100 @@ -156,8 +156,6 @@ old_gen->verify_object_start_array(); } - heap->pre_full_gc_dump(_gc_timer); - // Filled in below to track the state of the young gen after the collection. bool eden_empty; bool survivors_empty; @@ -168,6 +166,9 @@ GCTraceCPUTime tcpu; GCTraceTime(Info, gc) t("Pause Full", NULL, gc_cause, true); + + heap->pre_full_gc_dump(_gc_timer); + TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); @@ -345,6 +346,8 @@ // Track memory usage and detect low memory MemoryService::track_memory_usage(); heap->update_counters(); + + heap->post_full_gc_dump(_gc_timer); } if (VerifyAfterGC && heap->total_collections() >= VerifyGCStartAt) { @@ -367,8 +370,6 @@ heap->print_heap_after_gc(); heap->trace_heap_after_gc(_gc_tracer); - heap->post_full_gc_dump(_gc_timer); - #ifdef TRACESPINNING ParallelTaskTerminator::print_termination_counts(); #endif --- old/src/share/vm/gc/parallel/psParallelCompact.cpp 2016-02-05 08:24:07.661020929 +0100 +++ new/src/share/vm/gc/parallel/psParallelCompact.cpp 2016-02-05 08:24:07.553020924 +0100 @@ -1746,8 +1746,6 @@ heap->record_gen_tops_before_GC(); } - heap->pre_full_gc_dump(&_gc_timer); - // Make sure data structures are sane, make the heap parsable, and do other // miscellaneous bookkeeping. pre_compact(); @@ -1768,6 +1766,9 @@ GCTraceCPUTime tcpu; GCTraceTime(Info, gc) tm("Pause Full", NULL, gc_cause, true); + + heap->pre_full_gc_dump(&_gc_timer); + TraceCollectorStats tcs(counters()); TraceMemoryManagerStats tms(true /* Full GC */,gc_cause); @@ -1902,6 +1903,8 @@ MemoryService::track_memory_usage(); heap->update_counters(); gc_task_manager()->release_idle_workers(); + + heap->post_full_gc_dump(&_gc_timer); } #ifdef ASSERT @@ -1940,8 +1943,6 @@ collection_exit.ticks()); gc_task_manager()->print_task_time_stamps(); - heap->post_full_gc_dump(&_gc_timer); - #ifdef TRACESPINNING ParallelTaskTerminator::print_termination_counts(); #endif --- old/src/share/vm/gc/serial/tenuredGeneration.cpp 2016-02-05 08:24:07.917020939 +0100 +++ new/src/share/vm/gc/serial/tenuredGeneration.cpp 2016-02-05 08:24:07.789020934 +0100 @@ -176,8 +176,12 @@ SerialOldTracer* gc_tracer = GenMarkSweep::gc_tracer(); gc_tracer->report_gc_start(gch->gc_cause(), gc_timer->gc_start()); + gch->pre_full_gc_dump(gc_timer); + GenMarkSweep::invoke_at_safepoint(ref_processor(), clear_all_soft_refs); + gch->post_full_gc_dump(gc_timer); + gc_timer->register_gc_end(); gc_tracer->report_gc_end(gc_timer->gc_end(), gc_timer->time_partitions()); --- old/src/share/vm/gc/shared/collectedHeap.cpp 2016-02-05 08:24:08.129020948 +0100 +++ new/src/share/vm/gc/shared/collectedHeap.cpp 2016-02-05 08:24:08.017020943 +0100 @@ -572,19 +572,16 @@ } void CollectedHeap::full_gc_dump(GCTimer* timer, bool before) { + assert(timer != NULL, "timer is null"); if ((HeapDumpBeforeFullGC && before) || (HeapDumpAfterFullGC && !before)) { - GCIdMarkAndRestore gc_id_mark; - FormatBuffer<> title("Heap Dump (%s full gc)", before ? "before" : "after"); - GCTraceTime(Info, gc) tm(title.buffer(), timer); + GCTraceTime(Info, gc) tm(before ? "Heap Dump (before full gc)" : "Heap Dump (after full gc)", timer); HeapDumper::dump_heap(); } + LogHandle(gc, classhisto) log; if (log.is_trace()) { + GCTraceTime(Trace, gc, classhisto) tm(before ? "Class Histogram (before full gc)" : "Class Histogram (after full gc)", timer); ResourceMark rm; - GCIdMarkAndRestore gc_id_mark; - FormatBuffer<> title("Class Histogram (%s full gc)", - before ? "before" : "after"); - GCTraceTime(Trace, gc, classhisto) tm(title.buffer(), timer); VM_GC_HeapInspection inspector(log.trace_stream(), false /* ! full gc */); inspector.doit(); } --- old/src/share/vm/gc/shared/genCollectedHeap.cpp 2016-02-05 08:24:08.349020957 +0100 +++ new/src/share/vm/gc/shared/genCollectedHeap.cpp 2016-02-05 08:24:08.237020953 +0100 @@ -481,8 +481,6 @@ increment_total_full_collections(); } - pre_full_gc_dump(NULL); // do any pre full gc dumps - if (!prepared_for_verification && run_verification && VerifyGCLevel <= 1 && VerifyBeforeGC) { prepare_for_verify(); @@ -507,11 +505,6 @@ // a whole heap collection. complete = complete || collected_old; - if (complete) { // We did a full collection - // FIXME: See comment at pre_full_gc_dump call - post_full_gc_dump(NULL); // do any post full gc dumps - } - print_heap_change(young_prev_used, old_prev_used); MetaspaceAux::print_metaspace_change(metadata_prev_used); --- old/src/share/vm/logging/logPrefix.hpp 2016-02-05 08:24:08.557020966 +0100 +++ new/src/share/vm/logging/logPrefix.hpp 2016-02-05 08:24:08.449020961 +0100 @@ -43,6 +43,7 @@ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, age)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, alloc)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, barrier)) \ + LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, classhisto)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, compaction)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, compaction, phases)) \ LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, cpu)) \ --- old/src/share/vm/memory/heapInspection.cpp 2016-02-05 08:24:08.741020974 +0100 +++ new/src/share/vm/memory/heapInspection.cpp 2016-02-05 08:24:08.637020969 +0100 @@ -226,9 +226,8 @@ return (*e1)->compare(*e1,*e2); } -KlassInfoHisto::KlassInfoHisto(KlassInfoTable* cit, const char* title) : - _cit(cit), - _title(title) { +KlassInfoHisto::KlassInfoHisto(KlassInfoTable* cit) : + _cit(cit) { _elements = new (ResourceObj::C_HEAP, mtInternal) GrowableArray(_histo_initial_size, true); } @@ -648,7 +647,8 @@ if (print_stats) { print_class_stats(st, csv_format, columns); } else { - st->print_cr("%s",title()); + st->print_cr(" num #instances #bytes class name"); + st->print_cr("----------------------------------------------"); print_elements(st); } } @@ -729,10 +729,7 @@ } // Sort and print klass instance info - const char *title = "\n" - " num #instances #bytes class name\n" - "----------------------------------------------"; - KlassInfoHisto histo(&cit, title); + KlassInfoHisto histo(&cit); HistoClosure hc(&histo); cit.iterate(&hc); --- old/src/share/vm/memory/heapInspection.hpp 2016-02-05 08:24:08.961020983 +0100 +++ new/src/share/vm/memory/heapInspection.hpp 2016-02-05 08:24:08.845020978 +0100 @@ -281,8 +281,6 @@ KlassInfoTable *_cit; GrowableArray* _elements; GrowableArray* elements() const { return _elements; } - const char* _title; - const char* title() const { return _title; } static int sort_helper(KlassInfoEntry** e1, KlassInfoEntry** e2); void print_elements(outputStream* st) const; void print_class_stats(outputStream* st, bool csv_format, const char *columns); @@ -340,7 +338,7 @@ } public: - KlassInfoHisto(KlassInfoTable* cit, const char* title); + KlassInfoHisto(KlassInfoTable* cit); ~KlassInfoHisto(); void add(KlassInfoEntry* cie); void print_histo_on(outputStream* st, bool print_class_stats, bool csv_format, const char *columns);