35061
|
1 |
/*
|
|
2 |
* Copyright (c) 2012, 2015, Oracle and/or its affiliates. All rights reserved.
|
|
3 |
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
|
|
4 |
*
|
|
5 |
* This code is free software; you can redistribute it and/or modify it
|
|
6 |
* under the terms of the GNU General Public License version 2 only, as
|
|
7 |
* published by the Free Software Foundation.
|
|
8 |
*
|
|
9 |
* This code is distributed in the hope that it will be useful, but WITHOUT
|
|
10 |
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
|
|
11 |
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
|
|
12 |
* version 2 for more details (a copy is included in the LICENSE file that
|
|
13 |
* accompanied this code).
|
|
14 |
*
|
|
15 |
* You should have received a copy of the GNU General Public License version
|
|
16 |
* 2 along with this work; if not, write to the Free Software Foundation,
|
|
17 |
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
|
|
18 |
*
|
|
19 |
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
|
|
20 |
* or visit www.oracle.com if you need additional information or have any
|
|
21 |
* questions.
|
|
22 |
*
|
|
23 |
*/
|
|
24 |
|
|
25 |
#ifndef SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP
|
|
26 |
#define SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP
|
|
27 |
|
|
28 |
#include "gc/shared/collectedHeap.hpp"
|
|
29 |
#include "gc/shared/gcTimer.hpp"
|
|
30 |
#include "gc/shared/gcTrace.hpp"
|
|
31 |
#include "gc/shared/gcTraceTime.hpp"
|
|
32 |
#include "logging/log.hpp"
|
37255
|
33 |
#include "logging/logStream.inline.hpp"
|
35061
|
34 |
#include "memory/universe.hpp"
|
|
35 |
#include "prims/jni_md.h"
|
|
36 |
#include "utilities/ticks.hpp"
|
|
37 |
|
|
38 |
#define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
|
|
39 |
#define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
|
|
40 |
|
37255
|
41 |
inline void GCTraceTimeImpl::log_start(jlong start_counter) {
|
|
42 |
if (_out_start.is_enabled()) {
|
|
43 |
LogStream out(_out_start);
|
37200
|
44 |
|
37255
|
45 |
out.print("%s", _title);
|
35061
|
46 |
if (_gc_cause != GCCause::_no_gc) {
|
37255
|
47 |
out.print(" (%s)", GCCause::to_string(_gc_cause));
|
35061
|
48 |
}
|
37255
|
49 |
out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
|
35061
|
50 |
}
|
|
51 |
}
|
|
52 |
|
37255
|
53 |
inline void GCTraceTimeImpl::log_stop(jlong start_counter, jlong stop_counter) {
|
35061
|
54 |
double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter);
|
|
55 |
double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter);
|
|
56 |
double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter);
|
37255
|
57 |
|
|
58 |
LogStream out(_out_stop);
|
|
59 |
|
|
60 |
out.print("%s", _title);
|
|
61 |
|
35061
|
62 |
if (_gc_cause != GCCause::_no_gc) {
|
37255
|
63 |
out.print(" (%s)", GCCause::to_string(_gc_cause));
|
35061
|
64 |
}
|
37255
|
65 |
|
|
66 |
if (_heap_usage_before != SIZE_MAX) {
|
35061
|
67 |
CollectedHeap* heap = Universe::heap();
|
|
68 |
size_t used_before_m = _heap_usage_before / M;
|
|
69 |
size_t used_m = heap->used() / M;
|
|
70 |
size_t capacity_m = heap->capacity() / M;
|
37255
|
71 |
out.print(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m);
|
35061
|
72 |
}
|
37255
|
73 |
|
|
74 |
out.print_cr(" " LOG_STOP_TIME_FORMAT, start_time_in_secs, stop_time_in_secs, duration_in_ms);
|
35061
|
75 |
}
|
|
76 |
|
37255
|
77 |
inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) {
|
35061
|
78 |
if (_enabled || _timer != NULL) {
|
|
79 |
ticks.stamp();
|
|
80 |
}
|
|
81 |
}
|
|
82 |
|
37255
|
83 |
inline GCTraceTimeImpl::GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) :
|
|
84 |
_enabled(out_stop.is_enabled()),
|
|
85 |
_out_start(out_start),
|
|
86 |
_out_stop(out_stop),
|
35061
|
87 |
_start_ticks(),
|
|
88 |
_heap_usage_before(SIZE_MAX),
|
|
89 |
_title(title),
|
|
90 |
_gc_cause(gc_cause),
|
|
91 |
_timer(timer) {
|
|
92 |
|
|
93 |
time_stamp(_start_ticks);
|
|
94 |
if (_enabled) {
|
|
95 |
if (log_heap_usage) {
|
|
96 |
_heap_usage_before = Universe::heap()->used();
|
|
97 |
}
|
|
98 |
log_start(_start_ticks.value());
|
|
99 |
}
|
|
100 |
if (_timer != NULL) {
|
|
101 |
_timer->register_gc_phase_start(_title, _start_ticks);
|
|
102 |
}
|
|
103 |
}
|
|
104 |
|
37255
|
105 |
inline GCTraceTimeImpl::~GCTraceTimeImpl() {
|
35061
|
106 |
Ticks stop_ticks;
|
|
107 |
time_stamp(stop_ticks);
|
|
108 |
if (_enabled) {
|
|
109 |
log_stop(_start_ticks.value(), stop_ticks.value());
|
|
110 |
}
|
|
111 |
if (_timer != NULL) {
|
|
112 |
_timer->register_gc_phase_end(stop_ticks);
|
|
113 |
}
|
|
114 |
}
|
|
115 |
|
|
116 |
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
|
|
117 |
GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) :
|
37242
|
118 |
_enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
|
35061
|
119 |
if (_enabled) {
|
37242
|
120 |
LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time));
|
35061
|
121 |
}
|
|
122 |
}
|
|
123 |
|
|
124 |
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
|
|
125 |
GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() {
|
|
126 |
if (_enabled) {
|
|
127 |
jlong stop_time = os::elapsed_counter();
|
37242
|
128 |
LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
|
35061
|
129 |
_title,
|
|
130 |
TimeHelper::counter_to_seconds(_start_time),
|
|
131 |
TimeHelper::counter_to_seconds(stop_time),
|
|
132 |
TimeHelper::counter_to_millis(stop_time - _start_time));
|
|
133 |
}
|
|
134 |
}
|
|
135 |
|
37255
|
136 |
// Figure out the first __NO_TAG position and replace it with 'start'.
|
|
137 |
#define INJECT_START_TAG(T1, T2, T3, T4) \
|
|
138 |
(( T1 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T1), \
|
|
139 |
((T1 != LogTag::__NO_TAG && T2 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T2), \
|
|
140 |
((T2 != LogTag::__NO_TAG && T3 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T3), \
|
|
141 |
((T3 != LogTag::__NO_TAG && T4 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T4)
|
|
142 |
|
|
143 |
template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
|
|
144 |
GCTraceTimeImplWrapper<level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImplWrapper(
|
|
145 |
const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage)
|
|
146 |
: _impl(
|
|
147 |
LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(),
|
|
148 |
LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(),
|
|
149 |
title,
|
|
150 |
timer,
|
|
151 |
gc_cause,
|
|
152 |
log_heap_usage) {
|
|
153 |
|
|
154 |
STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
|
|
155 |
STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
|
|
156 |
}
|
|
157 |
|
|
158 |
#undef INJECT_START_TAG
|
|
159 |
|
|
160 |
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
|
|
161 |
GCTraceTimeImplWrapper<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceTimeImplWrapper() {}
|
|
162 |
|
|
163 |
#define GCTraceTime(Level, ...) GCTraceTimeImplWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
|
35061
|
164 |
#define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
|
|
165 |
|
|
166 |
#endif // SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP
|