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 #include "precompiled.hpp"
26 #include "gc/shared/gcTimer.hpp"
27 #include "utilities/growableArray.hpp"
28 #include "utilities/ticks.inline.hpp"
29
30 // the "time" parameter for most functions
31 // has a default value set by Ticks::now()
32
33 void GCTimer::register_gc_start(const Ticks& time) {
34 _time_partitions.clear();
35 _gc_start = time;
36 }
37
38 void GCTimer::register_gc_end(const Ticks& time) {
39 assert(!_time_partitions.has_active_phases(),
40 "We should have ended all started phases, before ending the GC");
41
42 _gc_end = time;
43 }
44
45 void GCTimer::register_gc_pause_start(const char* name, const Ticks& time) {
46 _time_partitions.report_gc_phase_start(name, time);
47 }
48
49 void GCTimer::register_gc_pause_end(const Ticks& time) {
50 _time_partitions.report_gc_phase_end(time);
51 }
52
53 void GCTimer::register_gc_phase_start(const char* name, const Ticks& time) {
54 _time_partitions.report_gc_phase_start(name, time);
55 }
56
57 void GCTimer::register_gc_phase_end(const Ticks& time) {
58 _time_partitions.report_gc_phase_end(time);
59 }
60
61 void STWGCTimer::register_gc_start(const Ticks& time) {
62 GCTimer::register_gc_start(time);
63 register_gc_pause_start("GC Pause", time);
64 }
65
66 void STWGCTimer::register_gc_end(const Ticks& time) {
67 register_gc_pause_end(time);
68 GCTimer::register_gc_end(time);
69 }
70
71 void ConcurrentGCTimer::register_gc_pause_start(const char* name) {
72 assert(!_is_concurrent_phase_active, "A pause phase can't be started while a concurrent phase is active.");
73 GCTimer::register_gc_pause_start(name);
74 }
75
76 void ConcurrentGCTimer::register_gc_pause_end() {
77 assert(!_is_concurrent_phase_active, "A pause phase can't be ended while a concurrent phase is active.");
78 GCTimer::register_gc_pause_end();
79 }
80
81 void ConcurrentGCTimer::register_gc_concurrent_start(const char* name, const Ticks& time) {
82 assert(!_is_concurrent_phase_active, "A concurrent phase is already active.");
83 _time_partitions.report_gc_phase_start(name, time, GCPhase::ConcurrentPhaseType);
84 _is_concurrent_phase_active = true;
85 }
86
87 void ConcurrentGCTimer::register_gc_concurrent_end(const Ticks& time) {
88 assert(_is_concurrent_phase_active, "A concurrent phase is not active.");
89 _time_partitions.report_gc_phase_end(time, GCPhase::ConcurrentPhaseType);
90 _is_concurrent_phase_active = false;
91 }
92
93 void PhasesStack::clear() {
94 _next_phase_level = 0;
95 }
96
97 void PhasesStack::push(int phase_index) {
98 assert(_next_phase_level < PHASE_LEVELS, "Overflow");
99
100 _phase_indices[_next_phase_level] = phase_index;
101 _next_phase_level++;
102 }
103
104 int PhasesStack::pop() {
105 assert(_next_phase_level > 0, "Underflow");
106
107 _next_phase_level--;
108 return _phase_indices[_next_phase_level];
109 }
110
111 int PhasesStack::count() const {
112 return _next_phase_level;
113 }
114
115 TimePartitions::TimePartitions() {
116 _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<GCPhase>(INITIAL_CAPACITY, true, mtGC);
117 clear();
118 }
119
120 TimePartitions::~TimePartitions() {
121 delete _phases;
122 _phases = NULL;
123 }
124
125 void TimePartitions::clear() {
126 _phases->clear();
127 _active_phases.clear();
128 _sum_of_pauses = Tickspan();
129 _longest_pause = Tickspan();
130 }
131
132 void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time, GCPhase::PhaseType type) {
133 assert(_phases->length() <= 1000, "Too many recored phases?");
134
135 int level = _active_phases.count();
136
137 GCPhase phase;
138 phase.set_type(type);
139 phase.set_level(level);
140 phase.set_name(name);
141 phase.set_start(time);
142
143 int index = _phases->append(phase);
144
145 _active_phases.push(index);
146 }
147
148 void TimePartitions::update_statistics(GCPhase* phase) {
149 if ((phase->type() == GCPhase::PausePhaseType) && (phase->level() == 0)) {
150 const Tickspan pause = phase->end() - phase->start();
151 _sum_of_pauses += pause;
152 _longest_pause = MAX2(pause, _longest_pause);
153 }
154 }
155
156 void TimePartitions::report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type) {
157 int phase_index = _active_phases.pop();
158 GCPhase* phase = _phases->adr_at(phase_index);
159 phase->set_end(time);
160 update_statistics(phase);
161 }
162
163 int TimePartitions::num_phases() const {
164 return _phases->length();
165 }
166
167 GCPhase* TimePartitions::phase_at(int index) const {
168 assert(index >= 0, "Out of bounds");
169 assert(index < _phases->length(), "Out of bounds");
170
171 return _phases->adr_at(index);
172 }
173
174 bool TimePartitions::has_active_phases() {
175 return _active_phases.count() > 0;
176 }
177
178 bool TimePartitionPhasesIterator::has_next() {
179 return _next < _time_partitions->num_phases();
180 }
181
182 GCPhase* TimePartitionPhasesIterator::next() {
183 assert(has_next(), "Must have phases left");
184 return _time_partitions->phase_at(_next++);
185 }
186
187
188 /////////////// Unit tests ///////////////
189
190 #ifndef PRODUCT
191
192 class TimePartitionPhasesIteratorTest {
193 public:
194 static void all() {
195 one_pause();
196 two_pauses();
197 one_sub_pause_phase();
198 many_sub_pause_phases();
199 many_sub_pause_phases2();
200 max_nested_pause_phases();
201 one_concurrent();
202 }
203
204 static void validate_gc_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {
205 assert(phase->level() == level, "Incorrect level");
206 assert(strcmp(phase->name(), name) == 0, "Incorrect name");
207 assert(phase->start() == start, "Incorrect start");
208 assert(phase->end() == end, "Incorrect end");
209 }
210
211 static void one_pause() {
212 TimePartitions time_partitions;
213 time_partitions.report_gc_phase_start("PausePhase", 2);
214 time_partitions.report_gc_phase_end(8);
215
216 TimePartitionPhasesIterator iter(&time_partitions);
217
218 validate_gc_phase(iter.next(), 0, "PausePhase", 2, 8);
219 assert(time_partitions.sum_of_pauses() == Ticks(8) - Ticks(2), "Incorrect");
220 assert(time_partitions.longest_pause() == Ticks(8) - Ticks(2), "Incorrect");
221
222 assert(!iter.has_next(), "Too many elements");
223 }
224
225 static void two_pauses() {
226 TimePartitions time_partitions;
227 time_partitions.report_gc_phase_start("PausePhase1", 2);
228 time_partitions.report_gc_phase_end(3);
229 time_partitions.report_gc_phase_start("PausePhase2", 4);
230 time_partitions.report_gc_phase_end(6);
231
232 TimePartitionPhasesIterator iter(&time_partitions);
233
234 validate_gc_phase(iter.next(), 0, "PausePhase1", 2, 3);
235 validate_gc_phase(iter.next(), 0, "PausePhase2", 4, 6);
236
237 assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
238 assert(time_partitions.longest_pause() == Ticks(2) - Ticks(0), "Incorrect");
239
240 assert(!iter.has_next(), "Too many elements");
241 }
242
243 static void one_sub_pause_phase() {
244 TimePartitions time_partitions;
245 time_partitions.report_gc_phase_start("PausePhase", 2);
246 time_partitions.report_gc_phase_start("SubPhase", 3);
247 time_partitions.report_gc_phase_end(4);
248 time_partitions.report_gc_phase_end(5);
249
250 TimePartitionPhasesIterator iter(&time_partitions);
251
252 validate_gc_phase(iter.next(), 0, "PausePhase", 2, 5);
253 validate_gc_phase(iter.next(), 1, "SubPhase", 3, 4);
254
255 assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
256 assert(time_partitions.longest_pause() == Ticks(3) - Ticks(0), "Incorrect");
257
258 assert(!iter.has_next(), "Too many elements");
259 }
260
261 static void max_nested_pause_phases() {
262 TimePartitions time_partitions;
263 time_partitions.report_gc_phase_start("PausePhase", 2);
264 time_partitions.report_gc_phase_start("SubPhase1", 3);
265 time_partitions.report_gc_phase_start("SubPhase2", 4);
266 time_partitions.report_gc_phase_start("SubPhase3", 5);
267 time_partitions.report_gc_phase_end(6);
268 time_partitions.report_gc_phase_end(7);
269 time_partitions.report_gc_phase_end(8);
270 time_partitions.report_gc_phase_end(9);
271
272 TimePartitionPhasesIterator iter(&time_partitions);
273
274 validate_gc_phase(iter.next(), 0, "PausePhase", 2, 9);
275 validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);
276 validate_gc_phase(iter.next(), 2, "SubPhase2", 4, 7);
277 validate_gc_phase(iter.next(), 3, "SubPhase3", 5, 6);
278
279 assert(time_partitions.sum_of_pauses() == Ticks(7) - Ticks(0), "Incorrect");
280 assert(time_partitions.longest_pause() == Ticks(7) - Ticks(0), "Incorrect");
281
282 assert(!iter.has_next(), "Too many elements");
283 }
284
285 static void many_sub_pause_phases() {
286 TimePartitions time_partitions;
287 time_partitions.report_gc_phase_start("PausePhase", 2);
288
289 time_partitions.report_gc_phase_start("SubPhase1", 3);
290 time_partitions.report_gc_phase_end(4);
291 time_partitions.report_gc_phase_start("SubPhase2", 5);
292 time_partitions.report_gc_phase_end(6);
293 time_partitions.report_gc_phase_start("SubPhase3", 7);
294 time_partitions.report_gc_phase_end(8);
295 time_partitions.report_gc_phase_start("SubPhase4", 9);
296 time_partitions.report_gc_phase_end(10);
297
298 time_partitions.report_gc_phase_end(11);
299
300 TimePartitionPhasesIterator iter(&time_partitions);
301
302 validate_gc_phase(iter.next(), 0, "PausePhase", 2, 11);
303 validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 4);
304 validate_gc_phase(iter.next(), 1, "SubPhase2", 5, 6);
305 validate_gc_phase(iter.next(), 1, "SubPhase3", 7, 8);
306 validate_gc_phase(iter.next(), 1, "SubPhase4", 9, 10);
307
308 assert(time_partitions.sum_of_pauses() == Ticks(9) - Ticks(0), "Incorrect");
309 assert(time_partitions.longest_pause() == Ticks(9) - Ticks(0), "Incorrect");
310
311 assert(!iter.has_next(), "Too many elements");
312 }
313
314 static void many_sub_pause_phases2() {
315 TimePartitions time_partitions;
316 time_partitions.report_gc_phase_start("PausePhase", 2);
317
318 time_partitions.report_gc_phase_start("SubPhase1", 3);
319 time_partitions.report_gc_phase_start("SubPhase11", 4);
320 time_partitions.report_gc_phase_end(5);
321 time_partitions.report_gc_phase_start("SubPhase12", 6);
322 time_partitions.report_gc_phase_end(7);
323 time_partitions.report_gc_phase_end(8);
324 time_partitions.report_gc_phase_start("SubPhase2", 9);
325 time_partitions.report_gc_phase_start("SubPhase21", 10);
326 time_partitions.report_gc_phase_end(11);
327 time_partitions.report_gc_phase_start("SubPhase22", 12);
328 time_partitions.report_gc_phase_end(13);
329 time_partitions.report_gc_phase_end(14);
330 time_partitions.report_gc_phase_start("SubPhase3", 15);
331 time_partitions.report_gc_phase_end(16);
332
333 time_partitions.report_gc_phase_end(17);
334
335 TimePartitionPhasesIterator iter(&time_partitions);
336
337 validate_gc_phase(iter.next(), 0, "PausePhase", 2, 17);
338 validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);
339 validate_gc_phase(iter.next(), 2, "SubPhase11", 4, 5);
340 validate_gc_phase(iter.next(), 2, "SubPhase12", 6, 7);
341 validate_gc_phase(iter.next(), 1, "SubPhase2", 9, 14);
342 validate_gc_phase(iter.next(), 2, "SubPhase21", 10, 11);
343 validate_gc_phase(iter.next(), 2, "SubPhase22", 12, 13);
344 validate_gc_phase(iter.next(), 1, "SubPhase3", 15, 16);
345
346 assert(time_partitions.sum_of_pauses() == Ticks(15) - Ticks(0), "Incorrect");
347 assert(time_partitions.longest_pause() == Ticks(15) - Ticks(0), "Incorrect");
348
349 assert(!iter.has_next(), "Too many elements");
350 }
351
352 static void one_concurrent() {
353 TimePartitions time_partitions;
354 time_partitions.report_gc_phase_start("ConcurrentPhase", 2, GCPhase::ConcurrentPhaseType);
355 time_partitions.report_gc_phase_end(8, GCPhase::ConcurrentPhaseType);
356
357 TimePartitionPhasesIterator iter(&time_partitions);
358
359 validate_gc_phase(iter.next(), 0, "ConcurrentPhase", 2, 8);
360 // ConcurrentPhaseType should not affect to both 'sum_of_pauses()' and 'longest_pause()'.
361 assert(time_partitions.sum_of_pauses() == Tickspan(), "Incorrect");
362 assert(time_partitions.longest_pause() == Tickspan(), "Incorrect");
363
364 assert(!iter.has_next(), "Too many elements");
365 }
366 };
367
368 class GCTimerTest {
369 public:
370 static void all() {
371 gc_start();
372 gc_end();
373 }
374
375 static void gc_start() {
376 GCTimer gc_timer;
377 gc_timer.register_gc_start(1);
378
379 assert(gc_timer.gc_start() == 1, "Incorrect");
380 }
381
382 static void gc_end() {
383 GCTimer gc_timer;
384 gc_timer.register_gc_start(1);
385 gc_timer.register_gc_end(2);
386
387 assert(gc_timer.gc_end() == 2, "Incorrect");
388 }
389 };
390
391 void GCTimerAllTest::all() {
392 GCTimerTest::all();
393 TimePartitionPhasesIteratorTest::all();
394 }
395
396 #endif