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