Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8270014: Add scoped objects for g1 young gc verification and young gc internal timing #4768

Closed
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
@@ -2922,6 +2922,36 @@ class G1YoungGCTraceTime {
}
};

class G1YoungGCVerifierMark : public StackObj {
G1HeapVerifier::G1VerifyType _type;

static G1HeapVerifier::G1VerifyType young_collection_verify_type() {
G1CollectorState* state = G1CollectedHeap::heap()->collector_state();
if (state->in_concurrent_start_gc()) {
return G1HeapVerifier::G1VerifyConcurrentStart;
} else if (state->in_young_only_phase()) {
return G1HeapVerifier::G1VerifyYoungNormal;
} else {
return G1HeapVerifier::G1VerifyMixed;
}
}

public:
G1YoungGCVerifierMark() : _type(young_collection_verify_type()) {
G1CollectedHeap::heap()->verify_before_young_collection(_type);
}

~G1YoungGCVerifierMark() {
G1CollectedHeap::heap()->verify_after_young_collection(_type);
}
};

class G1YoungGCNotifyPauseMark : public StackObj {
public:
G1YoungGCNotifyPauseMark() { G1CollectedHeap::heap()->policy()->record_young_gc_pause_start(); }
~G1YoungGCNotifyPauseMark() { G1CollectedHeap::heap()->policy()->record_young_gc_pause_end(); }
};

G1HeapPrinterMark::G1HeapPrinterMark(G1CollectedHeap* g1h) : _g1h(g1h), _heap_transition(g1h) {
// This summary needs to be printed before incrementing total collections.
_g1h->rem_set()->print_periodic_summary_info("Before GC RS summary", _g1h->total_collections());
@@ -3053,8 +3083,8 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
// determining collector state.
G1YoungGCTraceTime tm(gc_cause());

// Young GC internal timing
policy()->note_gc_start();
// Young GC internal pause timing
G1YoungGCNotifyPauseMark npm;
// JFR
G1YoungGCJFRTracerMark jtm(_gc_timer_stw, _gc_tracer_stw, gc_cause());
// JStat/MXBeans
@@ -3069,15 +3099,14 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
// just to do that).
wait_for_root_region_scanning();

G1HeapVerifier::G1VerifyType verify_type = young_collection_verify_type();
verify_before_young_collection(verify_type);
G1YoungGCVerifierMark vm;
{
// Actual collection work starts and is executed (only) in this scope.

// The elapsed time induced by the start time below deliberately elides
// the possible verification above.
double sample_start_time_sec = os::elapsedTime();
policy()->record_collection_pause_start(sample_start_time_sec);
// Young GC internal collection timing. The elapsed time recorded in the
// policy for the collection deliberately elides verification (and some
// other trivial setup above).
policy()->record_young_collection_start();

calculate_collection_set(jtm.evacuation_info(), target_pause_time_ms);

@@ -3106,14 +3135,8 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
// modifies it to the next state.
jtm.report_pause_type(collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark));

double sample_end_time_sec = os::elapsedTime();
double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
policy()->record_collection_pause_end(pause_time_ms, concurrent_operation_is_full_mark);
policy()->record_young_collection_end(concurrent_operation_is_full_mark);
}
verify_after_young_collection(verify_type);

policy()->print_phases();

TASKQUEUE_STATS_ONLY(print_taskqueue_stats());
TASKQUEUE_STATS_ONLY(reset_taskqueue_stats());
}
@@ -3803,11 +3826,11 @@ void G1CollectedHeap::evacuate_next_optional_regions(G1ParScanThreadStateSet* pe
}

void G1CollectedHeap::evacuate_optional_collection_set(G1ParScanThreadStateSet* per_thread_states) {
const double gc_start_time_ms = phase_times()->cur_collection_start_sec() * 1000.0;
const double collection_start_time_ms = phase_times()->cur_collection_start_sec() * 1000.0;

while (!evacuation_failed() && _collection_set.optional_region_length() > 0) {

double time_used_ms = os::elapsedTime() * 1000.0 - gc_start_time_ms;
double time_used_ms = os::elapsedTime() * 1000.0 - collection_start_time_ms;
double time_left_ms = MaxGCPauseMillis - time_used_ms;

if (time_left_ms < 0 ||
@@ -146,6 +146,8 @@ class G1CollectedHeap : public CollectedHeap {
friend class G1GCAllocRegion;
friend class G1HeapVerifier;

friend class G1YoungGCVerifierMark;

// Closures used in implementation.
friend class G1ParScanThreadState;
friend class G1ParScanThreadStateSet;
@@ -192,7 +192,7 @@ void G1GCPhaseTimes::reset() {
_weak_phase_times.reset();
}

void G1GCPhaseTimes::note_gc_start() {
void G1GCPhaseTimes::record_gc_pause_start() {
_gc_start_counter = os::elapsed_counter();
reset();
}
@@ -211,7 +211,7 @@ double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
return 0.0;
}

void G1GCPhaseTimes::note_gc_end() {
void G1GCPhaseTimes::record_gc_pause_end() {
_gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);

double uninitialized = WorkerDataArray<double>::uninitialized();
@@ -519,8 +519,9 @@ void G1GCPhaseTimes::print_other(double accounted_ms) const {
}

void G1GCPhaseTimes::print() {
note_gc_end();

// Check if some time has been recorded for verification and only then print
// the message. We do not use Verify*GC here to print because VerifyGCType
// further limits actual verification.
if (_cur_verify_before_time_ms > 0.0) {
Copy link
Member

@albertnetymk albertnetymk Jul 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this if just checking whether verification is enabled or not? If so, can VerifyBeforeGC be used? Otherwise, it's unclear to me why we are comparing it with 0.0.

Copy link
Contributor Author

@tschatzl tschatzl Jul 14, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The if checks whether any verification work has been done (it will be > 0.0 if it has been set) in this pause. We can't just use VerifyBefore/AfterGC because verification before/after does not always run for all young gc pauses (see VerifyGCType).
If we want to change this (existing) behavior to like always print the time if the flag is enabled I would suggest to file another CR instead of hiding it here (I can do all that and the associated work if that is desired).

Copy link
Member

@albertnetymk albertnetymk Jul 14, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can't just use VerifyBefore/AfterGC because...

I see; thank you for the explanation.

If we want to change this (existing) behavior to like always print the time if the flag is enabled

Either that or just put some comment there, since in what situation the condition is true is not obvious. Ofc, this is very subjective.

debug_time("Verify Before", _cur_verify_before_time_ms);
}
@@ -532,6 +533,7 @@ void G1GCPhaseTimes::print() {
accounted_ms += print_post_evacuate_collection_set();
print_other(accounted_ms);

// See above comment on the _cur_verify_before_time_ms check.
if (_cur_verify_after_time_ms > 0.0) {
debug_time("Verify After", _cur_verify_after_time_ms);
}
@@ -206,7 +206,6 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
WeakProcessorTimes _weak_phase_times;

double worker_time(GCParPhases phase, uint worker);
void note_gc_end();
void reset();

template <class T>
@@ -234,7 +233,8 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {

public:
G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads);
void note_gc_start();
void record_gc_pause_start();
void record_gc_pause_end();
void print();
static const char* phase_name(GCParPhases phase);

@@ -113,8 +113,8 @@ void G1Policy::init(G1CollectedHeap* g1h, G1CollectionSet* collection_set) {
_collection_set->start_incremental_building();
}

void G1Policy::note_gc_start() {
phase_times()->note_gc_start();
void G1Policy::record_young_gc_pause_start() {
phase_times()->record_gc_pause_start();
}

class G1YoungLengthPredictor {
@@ -517,7 +517,8 @@ void G1Policy::record_concurrent_refinement_stats() {
}
}

void G1Policy::record_collection_pause_start(double start_time_sec) {
void G1Policy::record_young_collection_start() {
Ticks now = Ticks::now();
// We only need to do this here as the policy will only be applied
// to the GC we're about to start. so, no point is calculating this
// every time we calculate / recalculate the target young length.
@@ -528,7 +529,7 @@ void G1Policy::record_collection_pause_start(double start_time_sec) {
max_survivor_regions(), _g1h->num_used_regions(), _g1h->max_regions());
assert_used_and_recalculate_used_equal(_g1h);

phase_times()->record_cur_collection_start_sec(start_time_sec);
phase_times()->record_cur_collection_start_sec(now.seconds());

record_concurrent_refinement_stats();

@@ -628,11 +629,12 @@ double G1Policy::logged_cards_processing_time() const {
// Anything below that is considered to be zero
#define MIN_TIMER_GRANULARITY 0.0000001

void G1Policy::record_collection_pause_end(double pause_time_ms, bool concurrent_operation_is_full_mark) {
void G1Policy::record_young_collection_end(bool concurrent_operation_is_full_mark) {
G1GCPhaseTimes* p = phase_times();

double end_time_sec = os::elapsedTime();
double start_time_sec = phase_times()->cur_collection_start_sec();
double end_time_sec = Ticks::now().seconds();
double pause_time_ms = (end_time_sec - start_time_sec) * 1000.0;

G1GCPauseType this_pause = collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark);

@@ -889,7 +891,8 @@ void G1Policy::report_ihop_statistics() {
_ihop_control->print();
}

void G1Policy::print_phases() {
void G1Policy::record_young_gc_pause_end() {
phase_times()->record_gc_pause_end();
phase_times()->print();
}

@@ -1487,7 +1490,7 @@ void G1Policy::update_survival_estimates_for_next_collection() {
}

void G1Policy::transfer_survivors_to_cset(const G1SurvivorRegions* survivors) {
note_start_adding_survivor_regions();
start_adding_survivor_regions();

HeapRegion* last = NULL;
for (GrowableArrayIterator<HeapRegion*> it = survivors->regions()->begin();
@@ -1503,7 +1506,7 @@ void G1Policy::transfer_survivors_to_cset(const G1SurvivorRegions* survivors) {

last = curr;
}
note_stop_adding_survivor_regions();
stop_adding_survivor_regions();

// Don't clear the survivor list handles until the start of
// the next evacuation pause - we need it in order to re-tag
@@ -301,17 +301,19 @@ class G1Policy: public CHeapObj<mtGC> {

void init(G1CollectedHeap* g1h, G1CollectionSet* collection_set);

void note_gc_start();
// Record the start and end of the young gc pause.
void record_young_gc_pause_start();
void record_young_gc_pause_end();

bool need_to_start_conc_mark(const char* source, size_t alloc_word_size = 0);

bool concurrent_operation_is_full_mark(const char* msg = NULL);

bool about_to_start_mixed_phase() const;

// Record the start and end of an evacuation pause.
void record_collection_pause_start(double start_time_sec);
void record_collection_pause_end(double pause_time_ms, bool concurrent_operation_is_full_mark);
// Record the start and end of the actual collection part of the evacuation pause.
void record_young_collection_start();
void record_young_collection_end(bool concurrent_operation_is_full_mark);

// Record the start and end of a full collection.
void record_full_collection_start();
@@ -328,8 +330,6 @@ class G1Policy: public CHeapObj<mtGC> {
void record_concurrent_mark_cleanup_start();
void record_concurrent_mark_cleanup_end(bool has_rebuilt_remembered_sets);

void print_phases();

bool next_gc_should_be_mixed(const char* true_action_str,
const char* false_action_str) const;

@@ -427,11 +427,11 @@ class G1Policy: public CHeapObj<mtGC> {
return _max_survivor_regions;
}

void note_start_adding_survivor_regions() {
void start_adding_survivor_regions() {
_survivor_surv_rate_group->start_adding_regions();
}

void note_stop_adding_survivor_regions() {
void stop_adding_survivor_regions() {
_survivor_surv_rate_group->stop_adding_regions();
}

@@ -73,12 +73,12 @@ public static void runTest() throws Exception {

// This gives an array of lines containing eager reclaim of humongous regions
// log messages contents after the ":" in the following order for every GC:
// Humongous Regions: f->g
// Region Register: a.ams
// Eagerly Reclaim Humonguous Objects b.cms
// Humongous Total: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: c, Workers: 1
// Humongous Candidate: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: d, Workers: 1
// Humongous Reclaimed: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: e, Workers: 1
// Humongous Regions: f->g

String[] lines = Arrays.stream(output.getStdout().split("\\R"))
.filter(s -> (s.contains("Humongous") || s.contains("Region Register"))).map(s -> s.substring(s.indexOf(LogSeparator) + LogSeparator.length()))
@@ -87,12 +87,12 @@ public static void runTest() throws Exception {
Asserts.assertTrue(lines.length % 6 == 0, "There seems to be an unexpected amount of log messages (total: " + lines.length + ") per GC");

for (int i = 0; i < lines.length; i += 6) {
int total = Integer.parseInt(getSumValue(lines[i + 2]));
int candidate = Integer.parseInt(getSumValue(lines[i + 3]));
int reclaimed = Integer.parseInt(getSumValue(lines[i + 4]));
int total = Integer.parseInt(getSumValue(lines[i + 3]));
int candidate = Integer.parseInt(getSumValue(lines[i + 4]));
int reclaimed = Integer.parseInt(getSumValue(lines[i + 5]));

int before = Integer.parseInt(lines[i + 5].substring(0, 1));
int after = Integer.parseInt(lines[i + 5].substring(3, 4));
int before = Integer.parseInt(lines[i].substring(0, 1));
int after = Integer.parseInt(lines[i].substring(3, 4));
System.out.println("total " + total + " candidate " + candidate + " reclaimed " + reclaimed + " before " + before + " after " + after);

Asserts.assertEQ(total, candidate, "Not all humonguous objects are candidates");