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 "gc/shared/referenceProcessorPhaseTimes.hpp"
28 #include "gc/shared/referenceProcessor.inline.hpp"
29 #include "logging/log.hpp"
30
31 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers number,
32 ReferenceProcessorPhaseTimes* phase_times,
33 uint worker_id) :
34 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
35 assert (phase_times != NULL, "Invariant");
36
37 _worker_time = phase_times->worker_time_sec(phase_times->par_phase(number));
38 }
39
40 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcParPhases phase,
41 ReferenceProcessorPhaseTimes* phase_times,
42 uint worker_id) :
43 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
44 assert (phase_times != NULL, "Invariant");
45
46 _worker_time = phase_times->worker_time_sec(phase);
47 }
48
49 RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() {
186 size_t after_count = _rp->total_reference_count(ref_type);
187 size_t discovered = times->ref_discovered(ref_type);
188 times->set_ref_cleared(ref_type, discovered - after_count);
189 }
190
191 RefProcEnqueueTimeTracker::RefProcEnqueueTimeTracker(ReferenceProcessorPhaseTimes* phase_times,
192 ReferenceProcessorStats& stats) :
193 RefProcPhaseTimeBaseTracker("Reference Enqueuing", phase_times) {
194 phase_times->set_ref_enqueued(REF_SOFT, stats.soft_count());
195 phase_times->set_ref_enqueued(REF_WEAK, stats.weak_count());
196 phase_times->set_ref_enqueued(REF_FINAL, stats.final_count());
197 phase_times->set_ref_enqueued(REF_PHANTOM, stats.phantom_count());
198 }
199
200 RefProcEnqueueTimeTracker::~RefProcEnqueueTimeTracker() {
201 double elapsed = elapsed_time();
202
203 phase_times()->set_par_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed);
204 }
205
206 ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer,
207 uint max_gc_threads,
208 bool processing_is_mt) :
209 _gc_timer(gc_timer), _processing_is_mt(processing_is_mt) {
210
211 for (int i = 0; i < RefParPhaseMax; i++) {
212 _worker_time_sec[i] = new WorkerDataArray<double>(max_gc_threads, "Process lists (ms)");
213 _par_phase_time_ms[i] = uninitialized();
214 }
215
216 for (int i = 0; i < number_of_subclasses_of_ref; i++) {
217 _ref_proc_time_ms[i] = uninitialized();
218 _balance_queues_time_ms[i] = uninitialized();
219 _ref_cleared[i] = 0;
220 _ref_discovered[i] = 0;
221 _ref_enqueued[i] = 0;
222 }
223 }
224
225 inline int ref_type_2_index(ReferenceType ref_type) {
226 return ref_type - REF_SOFT;
227 }
228
229 #define ASSERT_PAR_PHASE(phase) assert(phase >= ReferenceProcessorPhaseTimes::SoftRefPhase1 && \
295 size_t ReferenceProcessorPhaseTimes::ref_discovered(ReferenceType ref_type) const {
296 ASSERT_REF_TYPE(ref_type);
297 return _ref_discovered[ref_type_2_index(ref_type)];
298 }
299
300 void ReferenceProcessorPhaseTimes::set_ref_discovered(ReferenceType ref_type, size_t count) {
301 ASSERT_REF_TYPE(ref_type);
302 _ref_discovered[ref_type_2_index(ref_type)] = count;
303 }
304
305 size_t ReferenceProcessorPhaseTimes::ref_enqueued(ReferenceType ref_type) const {
306 ASSERT_REF_TYPE(ref_type);
307 return _ref_enqueued[ref_type_2_index(ref_type)];
308 }
309
310 void ReferenceProcessorPhaseTimes::set_ref_enqueued(ReferenceType ref_type, size_t count) {
311 ASSERT_REF_TYPE(ref_type);
312 _ref_enqueued[ref_type_2_index(ref_type)] = count;
313 }
314
315 double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceType ref_type) const{
316 ASSERT_REF_TYPE(ref_type);
317 return _balance_queues_time_ms[ref_type_2_index(ref_type)];
318 }
319
320 void ReferenceProcessorPhaseTimes::set_balance_queues_time_ms(ReferenceType ref_type, double time_ms) {
321 ASSERT_REF_TYPE(ref_type);
322 _balance_queues_time_ms[ref_type_2_index(ref_type)] = time_ms;
323 }
324
325 ReferenceProcessorPhaseTimes::RefProcParPhases
326 ReferenceProcessorPhaseTimes::par_phase(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers phase_number) const {
327 ASSERT_PHASE_NUMBER(phase_number);
328 ASSERT_REF_TYPE(_processing_ref_type);
329
330 int result = ReferenceProcessorPhaseTimes::SoftRefPhase1;
331
332 switch(_processing_ref_type) {
333 case REF_SOFT:
334 result = (int)ReferenceProcessorPhaseTimes::SoftRefPhase1;
335 result += phase_number;
336
337 assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::SoftRefPhase1 &&
338 (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::SoftRefPhase3,
339 "Invariant (%d)", result);
340 break;
341 case REF_WEAK:
342 result = (int)ReferenceProcessorPhaseTimes::WeakRefPhase2;
343 result += (phase_number - 1);
344 assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::WeakRefPhase2 &&
345 (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::WeakRefPhase3,
346 "Invariant (%d)", result);
347 break;
348 case REF_FINAL:
349 result = (int)ReferenceProcessorPhaseTimes::FinalRefPhase2;
350 result += (phase_number - 1);
351 assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::FinalRefPhase2 &&
352 (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::FinalRefPhase3,
353 "Invariant (%d)", result);
354 break;
355 case REF_PHANTOM:
356 result = (int)ReferenceProcessorPhaseTimes::PhantomRefPhase2;
357 result += (phase_number - 1);
358 assert((RefProcParPhases)result >= ReferenceProcessorPhaseTimes::PhantomRefPhase2 &&
359 (RefProcParPhases)result <= ReferenceProcessorPhaseTimes::PhantomRefPhase3,
360 "Invariant (%d)", result);
361 break;
362 default:
363 ShouldNotReachHere();
364 }
365
366 ASSERT_PAR_PHASE(result);
367
368 return (RefProcParPhases)result;
369 }
370
371 void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) {
372 if (print_total) {
373 print_phase(ReferenceProcessorPhaseTimes::RefEnqueue, base_indent);
374 }
375
376 log_debug(gc, phases, ref)("%sReference Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT
377 " Final: " SIZE_FORMAT " Phantom: " SIZE_FORMAT ,
378 Indents[base_indent + 1], ref_enqueued(REF_SOFT), ref_enqueued(REF_WEAK),
379 ref_enqueued(REF_FINAL), ref_enqueued(REF_PHANTOM));
380 }
381
382 #define TIME_FORMAT "%.1lfms"
383
384 void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) {
385 if (print_total) {
386 Log(gc, phases, ref) log;
387
388 if (log.is_level(LogLevel::Debug)) {
389 log.debug_stream()->print_cr("%s%s: " TIME_FORMAT,
390 Indents[base_indent], "Reference Processing", total_time_ms());
391 }
392 }
393
394 uint next_indent = base_indent + 1;
395 print_reference(REF_SOFT, next_indent);
396 print_reference(REF_WEAK, next_indent);
397 print_reference(REF_FINAL, next_indent);
398 print_reference(REF_PHANTOM, next_indent);
399 }
400
401 void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) {
402 Log(gc, phases, ref) log;
403
404 if (log.is_level(LogLevel::Debug)) {
405 uint next_indent = base_indent + 1;
406 outputStream* out = log.debug_stream();
407 ResourceMark rm;
408
409 out->print_cr("%s%s: " TIME_FORMAT,
410 Indents[base_indent], ref_type_2_string(ref_type), ref_proc_time_ms(ref_type));
411
412 double balance_time = balance_queues_time_ms(ref_type);
413 if (balance_time != uninitialized()) {
414 out->print_cr("%s%s " TIME_FORMAT, Indents[next_indent], "Balance queues:", balance_time);
415 }
416
417 switch(ref_type) {
418 case REF_SOFT:
419 print_phase(SoftRefPhase1, next_indent);
420 print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase2, next_indent);
421 print_phase(ReferenceProcessorPhaseTimes::SoftRefPhase3, next_indent);
422 break;
423
424 case REF_WEAK:
425 print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase2, next_indent);
426 print_phase(ReferenceProcessorPhaseTimes::WeakRefPhase3, next_indent);
427 break;
428
429 case REF_FINAL:
430 print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase2, next_indent);
431 print_phase(ReferenceProcessorPhaseTimes::FinalRefPhase3, next_indent);
432 break;
433
434 case REF_PHANTOM:
435 print_phase(ReferenceProcessorPhaseTimes::PhantomRefPhase2, next_indent);
436 print_phase(ReferenceProcessorPhaseTimes::PhantomRefPhase3, next_indent);
437 break;
438
439 default:
440 ShouldNotReachHere();
441 }
442
443 out->print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Discovered:", ref_discovered(ref_type));
444 out->print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Cleared:", ref_cleared(ref_type));
445 }
446 }
447
448 void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) {
449 double phase_time = par_phase_time_ms(phase);
450 if (phase_time != uninitialized()) {
451 Log(gc, phases, ref) log;
452
453 log.debug_stream()->print_cr("%s%s%s " TIME_FORMAT,
454 Indents[indent],
455 phase_enum_2_phase_string(phase),
456 indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */
457 phase_time);
458 if (processing_is_mt() && log.is_level(LogLevel::Trace)) {
459 outputStream* out = log.trace_stream();
460
461 out->print("%s", Indents[indent + 1]);
462 // worker_time_sec is recorded in seconds but it will be printed in milliseconds.
463 worker_time_sec(phase)->print_summary_on(out, true);
464 }
465 }
466 }
467
468 #undef ASSERT_REF_TYPE
469 #undef ASSERT_PHASE_NUMBER
470 #undef ASSERT_PAR_PHASE
471 #undef TIME_FORMAT
|
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 "gc/shared/referenceProcessorPhaseTimes.hpp"
28 #include "gc/shared/referenceProcessor.inline.hpp"
29 #include "logging/log.hpp"
30 #include "logging/logStream.hpp"
31
32 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcPhaseNumbers number,
33 ReferenceProcessorPhaseTimes* phase_times,
34 uint worker_id) :
35 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
36 assert (phase_times != NULL, "Invariant");
37
38 _worker_time = phase_times->worker_time_sec(phase_times->par_phase(number));
39 }
40
41 RefProcWorkerTimeTracker::RefProcWorkerTimeTracker(ReferenceProcessorPhaseTimes::RefProcParPhases phase,
42 ReferenceProcessorPhaseTimes* phase_times,
43 uint worker_id) :
44 _worker_time(NULL), _start_time(os::elapsedTime()), _worker_id(worker_id) {
45 assert (phase_times != NULL, "Invariant");
46
47 _worker_time = phase_times->worker_time_sec(phase);
48 }
49
50 RefProcWorkerTimeTracker::~RefProcWorkerTimeTracker() {
187 size_t after_count = _rp->total_reference_count(ref_type);
188 size_t discovered = times->ref_discovered(ref_type);
189 times->set_ref_cleared(ref_type, discovered - after_count);
190 }
191
192 RefProcEnqueueTimeTracker::RefProcEnqueueTimeTracker(ReferenceProcessorPhaseTimes* phase_times,
193 ReferenceProcessorStats& stats) :
194 RefProcPhaseTimeBaseTracker("Reference Enqueuing", phase_times) {
195 phase_times->set_ref_enqueued(REF_SOFT, stats.soft_count());
196 phase_times->set_ref_enqueued(REF_WEAK, stats.weak_count());
197 phase_times->set_ref_enqueued(REF_FINAL, stats.final_count());
198 phase_times->set_ref_enqueued(REF_PHANTOM, stats.phantom_count());
199 }
200
201 RefProcEnqueueTimeTracker::~RefProcEnqueueTimeTracker() {
202 double elapsed = elapsed_time();
203
204 phase_times()->set_par_phase_time_ms(ReferenceProcessorPhaseTimes::RefEnqueue, elapsed);
205 }
206
207 ReferenceProcessorPhaseTimes::ReferenceProcessorPhaseTimes(GCTimer* gc_timer, uint max_gc_threads) :
208 _gc_timer(gc_timer), _processing_is_mt(false) {
209
210 for (int i = 0; i < RefParPhaseMax; i++) {
211 _worker_time_sec[i] = new WorkerDataArray<double>(max_gc_threads, "Process lists (ms)");
212 _par_phase_time_ms[i] = uninitialized();
213 }
214
215 for (int i = 0; i < number_of_subclasses_of_ref; i++) {
216 _ref_proc_time_ms[i] = uninitialized();
217 _balance_queues_time_ms[i] = uninitialized();
218 _ref_cleared[i] = 0;
219 _ref_discovered[i] = 0;
220 _ref_enqueued[i] = 0;
221 }
222 }
223
224 inline int ref_type_2_index(ReferenceType ref_type) {
225 return ref_type - REF_SOFT;
226 }
227
228 #define ASSERT_PAR_PHASE(phase) assert(phase >= ReferenceProcessorPhaseTimes::SoftRefPhase1 && \
294 size_t ReferenceProcessorPhaseTimes::ref_discovered(ReferenceType ref_type) const {
295 ASSERT_REF_TYPE(ref_type);
296 return _ref_discovered[ref_type_2_index(ref_type)];
297 }
298
299 void ReferenceProcessorPhaseTimes::set_ref_discovered(ReferenceType ref_type, size_t count) {
300 ASSERT_REF_TYPE(ref_type);
301 _ref_discovered[ref_type_2_index(ref_type)] = count;
302 }
303
304 size_t ReferenceProcessorPhaseTimes::ref_enqueued(ReferenceType ref_type) const {
305 ASSERT_REF_TYPE(ref_type);
306 return _ref_enqueued[ref_type_2_index(ref_type)];
307 }
308
309 void ReferenceProcessorPhaseTimes::set_ref_enqueued(ReferenceType ref_type, size_t count) {
310 ASSERT_REF_TYPE(ref_type);
311 _ref_enqueued[ref_type_2_index(ref_type)] = count;
312 }
313
314 double ReferenceProcessorPhaseTimes::balance_queues_time_ms(ReferenceType ref_type) const {
315 ASSERT_REF_TYPE(ref_type);
316 return _balance_queues_time_ms[ref_type_2_index(ref_type)];
317 }
318
319 void ReferenceProcessorPhaseTimes::set_balance_queues_time_ms(ReferenceType ref_type, double time_ms) {
320 ASSERT_REF_TYPE(ref_type);
321 _balance_queues_time_ms[ref_type_2_index(ref_type)] = time_ms;
322 }
323
324 ReferenceProcessorPhaseTimes::RefProcParPhases
325 ReferenceProcessorPhaseTimes::par_phase(RefProcPhaseNumbers phase_number) const {
326 ASSERT_PHASE_NUMBER(phase_number);
327 ASSERT_REF_TYPE(_processing_ref_type);
328
329 int result = SoftRefPhase1;
330
331 switch(_processing_ref_type) {
332 case REF_SOFT:
333 result = (int)SoftRefPhase1;
334 result += phase_number;
335
336 assert((RefProcParPhases)result >= SoftRefPhase1 &&
337 (RefProcParPhases)result <= SoftRefPhase3,
338 "Invariant (%d)", result);
339 break;
340 case REF_WEAK:
341 result = (int)WeakRefPhase2;
342 result += (phase_number - 1);
343 assert((RefProcParPhases)result >= WeakRefPhase2 &&
344 (RefProcParPhases)result <= WeakRefPhase3,
345 "Invariant (%d)", result);
346 break;
347 case REF_FINAL:
348 result = (int)FinalRefPhase2;
349 result += (phase_number - 1);
350 assert((RefProcParPhases)result >= FinalRefPhase2 &&
351 (RefProcParPhases)result <= FinalRefPhase3,
352 "Invariant (%d)", result);
353 break;
354 case REF_PHANTOM:
355 result = (int)PhantomRefPhase2;
356 result += (phase_number - 1);
357 assert((RefProcParPhases)result >= PhantomRefPhase2 &&
358 (RefProcParPhases)result <= PhantomRefPhase3,
359 "Invariant (%d)", result);
360 break;
361 default:
362 ShouldNotReachHere();
363 }
364
365 ASSERT_PAR_PHASE(result);
366
367 return (RefProcParPhases)result;
368 }
369
370 void ReferenceProcessorPhaseTimes::print_enqueue_phase(uint base_indent, bool print_total) const {
371 if (print_total) {
372 print_phase(RefEnqueue, base_indent);
373 }
374
375 log_debug(gc, phases, ref)("%sReference Counts: Soft: " SIZE_FORMAT " Weak: " SIZE_FORMAT
376 " Final: " SIZE_FORMAT " Phantom: " SIZE_FORMAT ,
377 Indents[base_indent + 1], ref_enqueued(REF_SOFT), ref_enqueued(REF_WEAK),
378 ref_enqueued(REF_FINAL), ref_enqueued(REF_PHANTOM));
379 }
380
381 #define TIME_FORMAT "%.1lfms"
382
383 void ReferenceProcessorPhaseTimes::print_all_references(uint base_indent, bool print_total) const {
384 if (print_total) {
385 LogTarget(Debug, gc, phases, ref) lt;
386
387 if (lt.is_enabled()) {
388 LogStream ls(lt);
389 ls.print_cr("%s%s: " TIME_FORMAT,
390 Indents[base_indent], "Reference Processing", total_time_ms());
391 }
392 }
393
394 uint next_indent = base_indent + 1;
395 print_reference(REF_SOFT, next_indent);
396 print_reference(REF_WEAK, next_indent);
397 print_reference(REF_FINAL, next_indent);
398 print_reference(REF_PHANTOM, next_indent);
399 }
400
401 void ReferenceProcessorPhaseTimes::print_reference(ReferenceType ref_type, uint base_indent) const {
402 LogTarget(Debug, gc, phases, ref) lt;
403
404 if (lt.is_enabled()) {
405 LogStream ls(lt);
406 uint next_indent = base_indent + 1;
407 ResourceMark rm;
408
409 ls.print_cr("%s%s: " TIME_FORMAT,
410 Indents[base_indent], ref_type_2_string(ref_type), ref_proc_time_ms(ref_type));
411
412 double balance_time = balance_queues_time_ms(ref_type);
413 if (balance_time != uninitialized()) {
414 ls.print_cr("%s%s " TIME_FORMAT, Indents[next_indent], "Balance queues:", balance_time);
415 }
416
417 switch(ref_type) {
418 case REF_SOFT:
419 print_phase(SoftRefPhase1, next_indent);
420 print_phase(SoftRefPhase2, next_indent);
421 print_phase(SoftRefPhase3, next_indent);
422 break;
423
424 case REF_WEAK:
425 print_phase(WeakRefPhase2, next_indent);
426 print_phase(WeakRefPhase3, next_indent);
427 break;
428
429 case REF_FINAL:
430 print_phase(FinalRefPhase2, next_indent);
431 print_phase(FinalRefPhase3, next_indent);
432 break;
433
434 case REF_PHANTOM:
435 print_phase(PhantomRefPhase2, next_indent);
436 print_phase(PhantomRefPhase3, next_indent);
437 break;
438
439 default:
440 ShouldNotReachHere();
441 }
442
443 ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Discovered:", ref_discovered(ref_type));
444 ls.print_cr("%s%s " SIZE_FORMAT, Indents[next_indent], "Cleared:", ref_cleared(ref_type));
445 }
446 }
447
448 void ReferenceProcessorPhaseTimes::print_phase(RefProcParPhases phase, uint indent) const {
449 double phase_time = par_phase_time_ms(phase);
450 if (phase_time != uninitialized()) {
451 LogTarget(Debug, gc, phases, ref) lt;
452
453 LogStream ls(lt);
454
455 ls.print_cr("%s%s%s " TIME_FORMAT,
456 Indents[indent],
457 phase_enum_2_phase_string(phase),
458 indent == 0 ? "" : ":", /* 0 indent logs don't need colon. */
459 phase_time);
460
461 LogTarget(Trace, gc, phases, ref) lt2;
462 if (_processing_is_mt && lt2.is_enabled()) {
463 LogStream ls(lt2);
464
465 ls.print("%s", Indents[indent + 1]);
466 // worker_time_sec is recorded in seconds but it will be printed in milliseconds.
467 worker_time_sec(phase)->print_summary_on(&ls, true);
468 }
469 }
470 }
471
472 #undef ASSERT_REF_TYPE
473 #undef ASSERT_PHASE_NUMBER
474 #undef ASSERT_PAR_PHASE
475 #undef TIME_FORMAT
|