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_HPP
26 #define SHARE_VM_GC_SHARED_GCTRACETIME_HPP
27
28 #include "gc/shared/collectedHeap.hpp"
29 #include "gc/shared/gcTimer.hpp"
30 #include "gc/shared/gcTrace.hpp"
31 #include "logging/log.hpp"
32 #include "memory/allocation.hpp"
33 #include "memory/resourceArea.hpp"
34 #include "memory/universe.hpp"
35 #include "prims/jni_md.h"
36 #include "utilities/ticks.hpp"
37 #include "runtime/timer.hpp"
38 #include "utilities/ticks.hpp"
39
40 class GCTraceCPUTime : public StackObj {
41 bool _active; // true if times will be measured and printed
42 double _starting_user_time; // user time at start of measurement
43 double _starting_system_time; // system time at start of measurement
44 double _starting_real_time; // real time at start of measurement
45 public:
46 GCTraceCPUTime();
47 ~GCTraceCPUTime();
48 };
49
50 #define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
51 #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
52
53 template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG,
54 LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG>
55 class GCTraceTimeImpl : public StackObj {
56 private:
57 bool _enabled;
58 Ticks _start_ticks;
59 const char* _title;
60 GCCause::Cause _gc_cause;
61 GCTimer* _timer;
62 size_t _heap_usage_before;
63
64 void log_start(jlong start_counter) {
65 if (Log<LogTag::start, T0, T1, T2, T3>::is_level(Level)) {
66 FormatBuffer<> start_msg("%s", _title);
67 if (_gc_cause != GCCause::_no_gc) {
68 start_msg.append(" (%s)", GCCause::to_string(_gc_cause));
69 }
70 start_msg.append(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
71 // Make sure to put the "start" tag last in the tag set
72 STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
73 STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
74 if (T1 == LogTag::__NO_TAG) {
75 Log<T0, LogTag::start>::template write<Level>("%s", start_msg.buffer());
76 } else if (T2 == LogTag::__NO_TAG) {
77 Log<T0, T1, LogTag::start>::template write<Level>("%s", start_msg.buffer());
78 } else if (T3 == LogTag::__NO_TAG) {
79 Log<T0, T1, T2, LogTag::start>::template write<Level>("%s", start_msg.buffer());
80 } else {
81 Log<T0, T1, T2, T3, LogTag::start>::template write<Level>("%s", start_msg.buffer());
82 }
83 }
84 }
85
86 void log_stop(jlong start_counter, jlong stop_counter) {
87 double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter);
88 double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter);
89 double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter);
90 FormatBuffer<> stop_msg("%s", _title);
91 if (_gc_cause != GCCause::_no_gc) {
92 stop_msg.append(" (%s)", GCCause::to_string(_gc_cause));
93 }
94 if (_heap_usage_before == SIZE_MAX) {
95 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
96 stop_msg.buffer(), start_time_in_secs, stop_time_in_secs, duration_in_ms);
97 } else {
98 CollectedHeap* heap = Universe::heap();
99 size_t used_before_m = _heap_usage_before / M;
100 size_t used_m = heap->used() / M;
101 size_t capacity_m = heap->capacity() / M;
102 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_HEAP_FORMAT " " LOG_STOP_TIME_FORMAT,
103 stop_msg.buffer(), used_before_m, used_m, capacity_m, start_time_in_secs, stop_time_in_secs, duration_in_ms);
104 }
105 }
106
107 void time_stamp(Ticks& ticks) {
108 if (_enabled || _timer != NULL) {
109 ticks.stamp();
110 }
111 }
112
113 public:
114 GCTraceTimeImpl(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false) :
115 _enabled(Log<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)),
116 _start_ticks(),
117 _heap_usage_before(SIZE_MAX),
118 _title(title),
119 _gc_cause(gc_cause),
120 _timer(timer) {
121
122 time_stamp(_start_ticks);
123 if (_enabled) {
124 if (log_heap_usage) {
125 _heap_usage_before = Universe::heap()->used();
126 }
127 log_start(_start_ticks.value());
128 }
129 if (_timer != NULL) {
130 _timer->register_gc_phase_start(_title, _start_ticks);
131 }
132 }
133
134 ~GCTraceTimeImpl() {
135 Ticks stop_ticks;
136 time_stamp(stop_ticks);
137 if (_enabled) {
138 log_stop(_start_ticks.value(), stop_ticks.value());
139 }
140 if (_timer != NULL) {
141 _timer->register_gc_phase_end(stop_ticks);
142 }
143 }
144 };
145
146 // Similar to GCTraceTimeImpl but is intended for concurrent phase logging,
147 // which is a bit simpler and should always print the start line, i.e. not add the "start" tag.
148 template <LogLevelType Level, LogTagType T0, LogTagType T1 = LogTag::__NO_TAG, LogTagType T2 = LogTag::__NO_TAG, LogTagType T3 = LogTag::__NO_TAG,
149 LogTagType T4 = LogTag::__NO_TAG, LogTagType GuardTag = LogTag::__NO_TAG>
150 class GCTraceConcTimeImpl : public StackObj {
151 private:
152 bool _enabled;
153 jlong _start_time;
154 const char* _title;
155 public:
156 GCTraceConcTimeImpl(const char* title) :
157 _enabled(Log<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
158 if (_enabled) {
159 Log<T0, T1, T2, T3, T4>::template write<Level>("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time));
160 }
161 }
162
163 ~GCTraceConcTimeImpl() {
164 if (_enabled) {
165 jlong stop_time = os::elapsed_counter();
166 Log<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
167 _title,
168 TimeHelper::counter_to_seconds(_start_time),
169 TimeHelper::counter_to_seconds(stop_time),
170 TimeHelper::counter_to_seconds(stop_time - _start_time));
171 }
172 }
173
174 jlong start_time() { return _start_time; }
175 };
176
177
178 #define GCTraceTime(Level, ...) GCTraceTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
179 #define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
180
181 #endif // SHARE_VM_GC_SHARED_GCTRACETIME_HPP