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"
33 #include "memory/universe.hpp"
34 #include "prims/jni_md.h"
35 #include "utilities/ticks.hpp"
36
37 #define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
38 #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
39
40 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
41 void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::log_start(jlong start_counter) {
42 STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
43 STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
44
45 // Get log with start tag appended (replace first occurrence of NO_TAG)
46 const LogTagType start_tag = PREFIX_LOG_TAG(start);
47 const LogTagType no_tag = PREFIX_LOG_TAG(_NO_TAG);
48 LogImpl<T0,
49 T1 == no_tag ? start_tag : T1,
50 T1 != no_tag && T2 == no_tag ? start_tag : T2,
51 T2 != no_tag && T3 == no_tag ? start_tag : T3,
52 T3 != no_tag && T4 == no_tag ? start_tag : T4
53 > log;
54
55 if (log.is_level(Level)) {
56 FormatBuffer<> start_msg("%s", _title);
57 if (_gc_cause != GCCause::_no_gc) {
58 start_msg.append(" (%s)", GCCause::to_string(_gc_cause));
59 }
60 start_msg.append(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
61 // Make sure to put the "start" tag last in the tag set
62 log.template write<Level>("%s", start_msg.buffer());
63 }
64 }
65
66 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
67 void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::log_stop(jlong start_counter, jlong stop_counter) {
68 double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter);
69 double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter);
70 double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter);
71 FormatBuffer<> stop_msg("%s", _title);
72 if (_gc_cause != GCCause::_no_gc) {
73 stop_msg.append(" (%s)", GCCause::to_string(_gc_cause));
74 }
75 if (_heap_usage_before == SIZE_MAX) {
76 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
77 stop_msg.buffer(), start_time_in_secs, stop_time_in_secs, duration_in_ms);
78 } else {
79 CollectedHeap* heap = Universe::heap();
80 size_t used_before_m = _heap_usage_before / M;
81 size_t used_m = heap->used() / M;
82 size_t capacity_m = heap->capacity() / M;
83 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_HEAP_FORMAT " " LOG_STOP_TIME_FORMAT,
84 stop_msg.buffer(), used_before_m, used_m, capacity_m, start_time_in_secs, stop_time_in_secs, duration_in_ms);
85 }
86 }
87
88 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
89 void GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::time_stamp(Ticks& ticks) {
90 if (_enabled || _timer != NULL) {
91 ticks.stamp();
92 }
93 }
94
95 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
96 GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImpl(const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) :
97 _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)),
98 _start_ticks(),
99 _heap_usage_before(SIZE_MAX),
100 _title(title),
101 _gc_cause(gc_cause),
102 _timer(timer) {
103
104 time_stamp(_start_ticks);
105 if (_enabled) {
106 if (log_heap_usage) {
107 _heap_usage_before = Universe::heap()->used();
108 }
109 log_start(_start_ticks.value());
110 }
111 if (_timer != NULL) {
112 _timer->register_gc_phase_start(_title, _start_ticks);
113 }
114 }
115
116 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
117 GCTraceTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceTimeImpl() {
118 Ticks stop_ticks;
119 time_stamp(stop_ticks);
120 if (_enabled) {
121 log_stop(_start_ticks.value(), stop_ticks.value());
122 }
123 if (_timer != NULL) {
124 _timer->register_gc_phase_end(stop_ticks);
125 }
126 }
127
128 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
129 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) :
130 _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
131 if (_enabled) {
132 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time));
133 }
134 }
135
136 template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
137 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() {
138 if (_enabled) {
139 jlong stop_time = os::elapsed_counter();
140 LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
141 _title,
142 TimeHelper::counter_to_seconds(_start_time),
143 TimeHelper::counter_to_seconds(stop_time),
144 TimeHelper::counter_to_millis(stop_time - _start_time));
145 }
146 }
147
148 #define GCTraceTime(Level, ...) GCTraceTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
149 #define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
150
151 #endif // SHARE_VM_GC_SHARED_GCTRACETIME_INLINE_HPP