8219096: Merge print_termination_stats code with current logging

Reviewed-by: lkorinth, kbarrett
This commit is contained in:
Thomas Schatzl 2019-02-20 14:30:33 +01:00
parent f4ac0a2e0f
commit eaab45a8b8
9 changed files with 53 additions and 64 deletions

View File

@ -321,16 +321,26 @@ void G1PLABAllocator::flush_and_retire_stats() {
}
}
void G1PLABAllocator::waste(size_t& wasted, size_t& undo_wasted) {
wasted = 0;
undo_wasted = 0;
size_t G1PLABAllocator::waste() const {
size_t result = 0;
for (uint state = 0; state < InCSetState::Num; state++) {
PLAB * const buf = _alloc_buffers[state];
if (buf != NULL) {
wasted += buf->waste();
undo_wasted += buf->undo_waste();
result += buf->waste();
}
}
return result;
}
size_t G1PLABAllocator::undo_waste() const {
size_t result = 0;
for (uint state = 0; state < InCSetState::Num; state++) {
PLAB * const buf = _alloc_buffers[state];
if (buf != NULL) {
result += buf->undo_waste();
}
}
return result;
}
bool G1ArchiveAllocator::_archive_check_enabled = false;

View File

@ -155,7 +155,8 @@ private:
public:
G1PLABAllocator(G1Allocator* allocator);
void waste(size_t& wasted, size_t& undo_wasted);
size_t waste() const;
size_t undo_waste() const;
// Allocate word_sz words in dest, either directly into the regions or by
// allocating a new PLAB. Returns the address of the allocated memory, NULL if

View File

@ -3299,27 +3299,22 @@ public:
G1GCPhaseTimes* p = _g1h->g1_policy()->phase_times();
p->add_time_secs(G1GCPhaseTimes::ObjCopy, worker_id, elapsed_sec - term_sec);
p->record_or_add_thread_work_item(G1GCPhaseTimes::ObjCopy,
worker_id,
pss->lab_waste_words() * HeapWordSize,
G1GCPhaseTimes::ObjCopyLABWaste);
p->record_or_add_thread_work_item(G1GCPhaseTimes::ObjCopy,
worker_id,
pss->lab_undo_waste_words() * HeapWordSize,
G1GCPhaseTimes::ObjCopyLABUndoWaste);
p->record_time_secs(G1GCPhaseTimes::Termination, worker_id, term_sec);
p->record_thread_work_item(G1GCPhaseTimes::Termination, worker_id, evac_term_attempts);
}
assert(pss->queue_is_empty(), "should be empty");
if (log_is_enabled(Debug, gc, task, stats)) {
MutexLockerEx x(ParGCRareEvent_lock, Mutex::_no_safepoint_check_flag);
size_t lab_waste;
size_t lab_undo_waste;
pss->waste(lab_waste, lab_undo_waste);
_g1h->print_termination_stats(worker_id,
(os::elapsedTime() - start_sec) * 1000.0, /* elapsed time */
strong_roots_sec * 1000.0, /* strong roots time */
term_sec * 1000.0, /* evac term time */
evac_term_attempts, /* evac term attempts */
lab_waste, /* alloc buffer waste */
lab_undo_waste /* undo waste */
);
}
// Close the inner scope so that the ResourceMark and HandleMark
// destructors are executed here and are included as part of the
// "GC Worker Time".
@ -3328,31 +3323,6 @@ public:
}
};
void G1CollectedHeap::print_termination_stats_hdr() {
log_debug(gc, task, stats)("GC Termination Stats");
log_debug(gc, task, stats)(" elapsed --strong roots-- -------termination------- ------waste (KiB)------");
log_debug(gc, task, stats)("thr ms ms %% ms %% attempts total alloc undo");
log_debug(gc, task, stats)("--- --------- --------- ------ --------- ------ -------- ------- ------- -------");
}
void G1CollectedHeap::print_termination_stats(uint worker_id,
double elapsed_ms,
double strong_roots_ms,
double term_ms,
size_t term_attempts,
size_t alloc_buffer_waste,
size_t undo_waste) const {
log_debug(gc, task, stats)
("%3d %9.2f %9.2f %6.2f "
"%9.2f %6.2f " SIZE_FORMAT_W(8) " "
SIZE_FORMAT_W(7) " " SIZE_FORMAT_W(7) " " SIZE_FORMAT_W(7),
worker_id, elapsed_ms, strong_roots_ms, strong_roots_ms * 100 / elapsed_ms,
term_ms, term_ms * 100 / elapsed_ms, term_attempts,
(alloc_buffer_waste + undo_waste) * HeapWordSize / K,
alloc_buffer_waste * HeapWordSize / K,
undo_waste * HeapWordSize / K);
}
void G1CollectedHeap::complete_cleaning(BoolObjectClosure* is_alive,
bool class_unloading_occurred) {
uint num_workers = workers()->active_workers();
@ -3763,8 +3733,6 @@ void G1CollectedHeap::evacuate_collection_set(G1ParScanThreadStateSet* per_threa
G1RootProcessor root_processor(this, n_workers);
G1ParTask g1_par_task(this, per_thread_states, _task_queues, &root_processor, n_workers);
print_termination_stats_hdr();
workers()->run_task(&g1_par_task);
end_par_time_sec = os::elapsedTime();

View File

@ -738,16 +738,6 @@ private:
void pre_evacuate_collection_set();
void post_evacuate_collection_set(G1EvacuationInfo& evacuation_info, G1ParScanThreadStateSet* pss);
// Print the header for the per-thread termination statistics.
static void print_termination_stats_hdr();
// Print actual per-thread termination statistics.
void print_termination_stats(uint worker_id,
double elapsed_ms,
double strong_roots_ms,
double term_ms,
size_t term_attempts,
size_t alloc_buffer_waste,
size_t undo_waste) const;
// Update object copying statistics.
void record_obj_copy_mem_stats();

View File

@ -107,6 +107,11 @@ G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
_update_rs_skipped_cards = new WorkerDataArray<size_t>(max_gc_threads, "Skipped Cards:");
_gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_skipped_cards, UpdateRSSkippedCards);
_obj_copy_lab_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Waste");
_gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_waste, ObjCopyLABWaste);
_obj_copy_lab_undo_waste = new WorkerDataArray<size_t>(max_gc_threads, "LAB Undo Waste");
_gc_par_phases[ObjCopy]->link_thread_work_items(_obj_copy_lab_undo_waste, ObjCopyLABUndoWaste);
_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:");
_gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);

View File

@ -93,6 +93,11 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
UpdateRSSkippedCards
};
enum GCObjCopyWorkItems {
ObjCopyLABWaste,
ObjCopyLABUndoWaste
};
enum GCOptCSetWorkItems {
OptCSetScannedCards,
OptCSetClaimedCards,
@ -114,6 +119,9 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
WorkerDataArray<size_t>* _scan_rs_claimed_cards;
WorkerDataArray<size_t>* _scan_rs_skipped_cards;
WorkerDataArray<size_t>* _obj_copy_lab_waste;
WorkerDataArray<size_t>* _obj_copy_lab_undo_waste;
WorkerDataArray<size_t>* _opt_cset_scanned_cards;
WorkerDataArray<size_t>* _opt_cset_claimed_cards;
WorkerDataArray<size_t>* _opt_cset_skipped_cards;

View File

@ -1,5 +1,5 @@
/*
* Copyright (c) 2014, 2018, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2014, 2019, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
@ -106,8 +106,12 @@ G1ParScanThreadState::~G1ParScanThreadState() {
delete[] _oops_into_optional_regions;
}
void G1ParScanThreadState::waste(size_t& wasted, size_t& undo_wasted) {
_plab_allocator->waste(wasted, undo_wasted);
size_t G1ParScanThreadState::lab_waste_words() const {
return _plab_allocator->waste();
}
size_t G1ParScanThreadState::lab_undo_waste_words() const {
return _plab_allocator->undo_waste();
}
#ifdef ASSERT

View File

@ -127,9 +127,8 @@ public:
G1EvacuationRootClosures* closures() { return _closures; }
uint worker_id() { return _worker_id; }
// Returns the current amount of waste due to alignment or not being able to fit
// objects within LABs and the undo waste.
virtual void waste(size_t& wasted, size_t& undo_wasted);
size_t lab_waste_words() const;
size_t lab_undo_waste_words() const;
size_t* surviving_young_words() {
// We add one to hide entry 0 which accumulates surviving words for

View File

@ -106,6 +106,10 @@ public class TestGCLogMessages {
new LogMessageWithLevel("Scanned Cards", Level.DEBUG),
new LogMessageWithLevel("Claimed Cards", Level.DEBUG),
new LogMessageWithLevel("Skipped Cards", Level.DEBUG),
// Object Copy
new LogMessageWithLevel("Object Copy", Level.DEBUG),
new LogMessageWithLevel("Scanned Cards", Level.DEBUG),
new LogMessageWithLevel("Claimed Cards", Level.DEBUG),
// Ext Root Scan
new LogMessageWithLevel("Thread Roots", Level.TRACE),
new LogMessageWithLevel("Universe Roots", Level.TRACE),