--- old/src/share/vm/gc/shared/threadLocalAllocBuffer.cpp 2015-12-01 12:06:25.302930226 +0100 +++ new/src/share/vm/gc/shared/threadLocalAllocBuffer.cpp 2015-12-01 12:06:25.182930230 +0100 @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "gc/shared/genCollectedHeap.hpp" #include "gc/shared/threadLocalAllocBuffer.inline.hpp" +#include "logging/log.hpp" #include "memory/resourceArea.hpp" #include "memory/universe.inline.hpp" #include "oops/oop.inline.hpp" @@ -54,9 +55,7 @@ // Publish new stats if some allocation occurred. if (global_stats()->allocation() != 0) { global_stats()->publish(); - if (PrintTLAB) { - global_stats()->print(); - } + global_stats()->print(); } } @@ -70,9 +69,7 @@ size_t allocated_since_last_gc = total_allocated - _allocated_before_last_gc; _allocated_before_last_gc = total_allocated; - if (PrintTLAB && (_number_of_refills > 0 || Verbose)) { - print_stats("gc"); - } + print_stats("gc"); if (_number_of_refills > 0) { // Update allocation history if a reasonable amount of eden was allocated. @@ -149,12 +146,11 @@ size_t aligned_new_size = align_object_size(new_size); - if (PrintTLAB && Verbose) { - gclog_or_tty->print("TLAB new size: thread: " INTPTR_FORMAT " [id: %2d]" - " refills %d alloc: %8.6f desired_size: " SIZE_FORMAT " -> " SIZE_FORMAT "\n", - p2i(myThread()), myThread()->osthread()->thread_id(), - _target_refills, _allocation_fraction.average(), desired_size(), aligned_new_size); - } + log_trace(gc, tlab)("TLAB new size: thread: " INTPTR_FORMAT " [id: %2d]" + " refills %d alloc: %8.6f desired_size: " SIZE_FORMAT " -> " SIZE_FORMAT, + p2i(myThread()), myThread()->osthread()->thread_id(), + _target_refills, _allocation_fraction.average(), desired_size(), aligned_new_size); + set_desired_size(aligned_new_size); set_refill_waste_limit(initial_refill_waste_limit()); } @@ -171,9 +167,7 @@ HeapWord* top, size_t new_size) { _number_of_refills++; - if (PrintTLAB && Verbose) { - print_stats("fill"); - } + print_stats("fill"); assert(top <= start + new_size - alignment_reserve(), "size too small"); initialize(start, top, start + new_size - alignment_reserve()); @@ -226,10 +220,8 @@ guarantee(Thread::current()->is_Java_thread(), "tlab initialization thread not Java thread"); Thread::current()->tlab().initialize(); - if (PrintTLAB && Verbose) { - gclog_or_tty->print("TLAB min: " SIZE_FORMAT " initial: " SIZE_FORMAT " max: " SIZE_FORMAT "\n", - min_size(), Thread::current()->tlab().initial_desired_size(), max_size()); - } + log_develop_trace(gc, tlab)("TLAB min: " SIZE_FORMAT " initial: " SIZE_FORMAT " max: " SIZE_FORMAT, + min_size(), Thread::current()->tlab().initial_desired_size(), max_size()); } size_t ThreadLocalAllocBuffer::initial_desired_size() { @@ -250,26 +242,31 @@ } void ThreadLocalAllocBuffer::print_stats(const char* tag) { + LogHandle(gc, tlab) log; + if (!log.is_trace()) { + return; + } + Thread* thrd = myThread(); size_t waste = _gc_waste + _slow_refill_waste + _fast_refill_waste; size_t alloc = _number_of_refills * _desired_size; double waste_percent = alloc == 0 ? 0.0 : 100.0 * waste / alloc; size_t tlab_used = Universe::heap()->tlab_used(thrd); - gclog_or_tty->print("TLAB: %s thread: " INTPTR_FORMAT " [id: %2d]" - " desired_size: " SIZE_FORMAT "KB" - " slow allocs: %d refill waste: " SIZE_FORMAT "B" - " alloc:%8.5f %8.0fKB refills: %d waste %4.1f%% gc: %dB" - " slow: %dB fast: %dB\n", - tag, p2i(thrd), thrd->osthread()->thread_id(), - _desired_size / (K / HeapWordSize), - _slow_allocations, _refill_waste_limit * HeapWordSize, - _allocation_fraction.average(), - _allocation_fraction.average() * tlab_used / K, - _number_of_refills, waste_percent, - _gc_waste * HeapWordSize, - _slow_refill_waste * HeapWordSize, - _fast_refill_waste * HeapWordSize); + log.trace("TLAB: %s thread: " INTPTR_FORMAT " [id: %2d]" + " desired_size: " SIZE_FORMAT "KB" + " slow allocs: %d refill waste: " SIZE_FORMAT "B" + " alloc:%8.5f %8.0fKB refills: %d waste %4.1f%% gc: %dB" + " slow: %dB fast: %dB", + tag, p2i(thrd), thrd->osthread()->thread_id(), + _desired_size / (K / HeapWordSize), + _slow_allocations, _refill_waste_limit * HeapWordSize, + _allocation_fraction.average(), + _allocation_fraction.average() * tlab_used / K, + _number_of_refills, waste_percent, + _gc_waste * HeapWordSize, + _slow_refill_waste * HeapWordSize, + _fast_refill_waste * HeapWordSize); } void ThreadLocalAllocBuffer::verify() { @@ -388,22 +385,27 @@ } void GlobalTLABStats::print() { + LogHandle(gc, tlab) log; + if (!log.is_debug()) { + return; + } + size_t waste = _total_gc_waste + _total_slow_refill_waste + _total_fast_refill_waste; double waste_percent = _total_allocation == 0 ? 0.0 : 100.0 * waste / _total_allocation; - gclog_or_tty->print("TLAB totals: thrds: %d refills: %d max: %d" - " slow allocs: %d max %d waste: %4.1f%%" - " gc: " SIZE_FORMAT "B max: " SIZE_FORMAT "B" - " slow: " SIZE_FORMAT "B max: " SIZE_FORMAT "B" - " fast: " SIZE_FORMAT "B max: " SIZE_FORMAT "B\n", - _allocating_threads, - _total_refills, _max_refills, - _total_slow_allocations, _max_slow_allocations, - waste_percent, - _total_gc_waste * HeapWordSize, - _max_gc_waste * HeapWordSize, - _total_slow_refill_waste * HeapWordSize, - _max_slow_refill_waste * HeapWordSize, - _total_fast_refill_waste * HeapWordSize, - _max_fast_refill_waste * HeapWordSize); + log.debug("TLAB totals: thrds: %d refills: %d max: %d" + " slow allocs: %d max %d waste: %4.1f%%" + " gc: " SIZE_FORMAT "B max: " SIZE_FORMAT "B" + " slow: " SIZE_FORMAT "B max: " SIZE_FORMAT "B" + " fast: " SIZE_FORMAT "B max: " SIZE_FORMAT "B", + _allocating_threads, + _total_refills, _max_refills, + _total_slow_allocations, _max_slow_allocations, + waste_percent, + _total_gc_waste * HeapWordSize, + _max_gc_waste * HeapWordSize, + _total_slow_refill_waste * HeapWordSize, + _max_slow_refill_waste * HeapWordSize, + _total_fast_refill_waste * HeapWordSize, + _max_fast_refill_waste * HeapWordSize); }