--- /dev/null 2015-08-17 09:33:10.330134408 +0200 +++ new/src/share/vm/gc/shared/gcTraceTime.inline.hpp 2015-12-01 12:06:39.834929719 +0100 @@ -0,0 +1,149 @@ +/* + * Copyright (c) 2012, 2015, 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 + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + * + */ + +#ifndef SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP +#define SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP + +#include "gc/shared/collectedHeap.hpp" +#include "gc/shared/gcTimer.hpp" +#include "gc/shared/gcTrace.hpp" +#include "gc/shared/gcTraceTime.hpp" +#include "logging/log.hpp" +#include "memory/universe.hpp" +#include "prims/jni_md.h" +#include "utilities/ticks.hpp" +#include "runtime/timer.hpp" + +#define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms" +#define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)" + +template +void GCTraceTimeImpl::log_start(jlong start_counter) { + if (Log::is_level(Level)) { + FormatBuffer<> start_msg("%s", _title); + if (_gc_cause != GCCause::_no_gc) { + start_msg.append(" (%s)", GCCause::to_string(_gc_cause)); + } + start_msg.append(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter)); + // Make sure to put the "start" tag last in the tag set + STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on. + STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start() + if (T1 == LogTag::__NO_TAG) { + Log::template write("%s", start_msg.buffer()); + } else if (T2 == LogTag::__NO_TAG) { + Log::template write("%s", start_msg.buffer()); + } else if (T3 == LogTag::__NO_TAG) { + Log::template write("%s", start_msg.buffer()); + } else { + Log::template write("%s", start_msg.buffer()); + } + } +} + +template +void GCTraceTimeImpl::log_stop(jlong start_counter, jlong stop_counter) { + double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter); + double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter); + double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter); + FormatBuffer<> stop_msg("%s", _title); + if (_gc_cause != GCCause::_no_gc) { + stop_msg.append(" (%s)", GCCause::to_string(_gc_cause)); + } + if (_heap_usage_before == SIZE_MAX) { + Log::template write("%s " LOG_STOP_TIME_FORMAT, + stop_msg.buffer(), start_time_in_secs, stop_time_in_secs, duration_in_ms); + } else { + CollectedHeap* heap = Universe::heap(); + size_t used_before_m = _heap_usage_before / M; + size_t used_m = heap->used() / M; + size_t capacity_m = heap->capacity() / M; + Log::template write("%s " LOG_STOP_HEAP_FORMAT " " LOG_STOP_TIME_FORMAT, + stop_msg.buffer(), used_before_m, used_m, capacity_m, start_time_in_secs, stop_time_in_secs, duration_in_ms); + } +} + +template +void GCTraceTimeImpl::time_stamp(Ticks& ticks) { + if (_enabled || _timer != NULL) { + ticks.stamp(); + } +} + +template +GCTraceTimeImpl::GCTraceTimeImpl(const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) : + _enabled(Log::is_level(Level)), + _start_ticks(), + _heap_usage_before(SIZE_MAX), + _title(title), + _gc_cause(gc_cause), + _timer(timer) { + + time_stamp(_start_ticks); + if (_enabled) { + if (log_heap_usage) { + _heap_usage_before = Universe::heap()->used(); + } + log_start(_start_ticks.value()); + } + if (_timer != NULL) { + _timer->register_gc_phase_start(_title, _start_ticks); + } +} + +template +GCTraceTimeImpl::~GCTraceTimeImpl() { + Ticks stop_ticks; + time_stamp(stop_ticks); + if (_enabled) { + log_stop(_start_ticks.value(), stop_ticks.value()); + } + if (_timer != NULL) { + _timer->register_gc_phase_end(stop_ticks); + } +} + +template +GCTraceConcTimeImpl::GCTraceConcTimeImpl(const char* title) : + _enabled(Log::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) { + if (_enabled) { + Log::template write("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time)); + } +} + +template +GCTraceConcTimeImpl::~GCTraceConcTimeImpl() { + if (_enabled) { + jlong stop_time = os::elapsed_counter(); + Log::template write("%s " LOG_STOP_TIME_FORMAT, + _title, + TimeHelper::counter_to_seconds(_start_time), + TimeHelper::counter_to_seconds(stop_time), + TimeHelper::counter_to_millis(stop_time - _start_time)); + } +} + +#define GCTraceTime(Level, ...) GCTraceTimeImpl +#define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl + +#endif // SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP