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 1 commit
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()->note_young_gc_pause_start(); }
~G1YoungGCNotifyPauseMark() { G1CollectedHeap::heap()->policy()->note_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();
@@ -247,6 +247,7 @@ void G1GCPhaseTimes::note_gc_end() {
ASSERT_PHASE_UNINITIALIZED(Termination);
}
}
print();
}

#undef ASSERT_PHASE_UNINITIALIZED
@@ -519,8 +520,6 @@ void G1GCPhaseTimes::print_other(double accounted_ms) const {
}

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

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);
}
@@ -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::note_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 start_time_s = phase_times()->cur_collection_start_sec();

Choose a reason for hiding this comment

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

I dislike this change of nomenclature to use _s suffix instead of _sec suffix to indicate units of seconds. The latter is in wide use in GC code.

double end_time_s = Ticks::now().seconds();
double pause_time_ms = (end_time_s - start_time_s) * 1000.0;

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

@@ -644,7 +646,7 @@ void G1Policy::record_collection_pause_end(double pause_time_ms, bool concurrent
maybe_start_marking();
}

double app_time_ms = (start_time_sec * 1000.0 - _analytics->prev_collection_pause_end_ms());
double app_time_ms = (start_time_s * 1000.0 - _analytics->prev_collection_pause_end_ms());
if (app_time_ms < MIN_TIMER_GRANULARITY) {
// This usually happens due to the timer not having the required
// granularity. Some Linuxes are the usual culprits.
@@ -666,7 +668,7 @@ void G1Policy::record_collection_pause_end(double pause_time_ms, bool concurrent
_analytics->report_alloc_rate_ms(alloc_rate_ms);
}

record_pause(this_pause, start_time_sec, end_time_sec);
record_pause(this_pause, start_time_s, end_time_s);

if (G1GCPauseTypeHelper::is_last_young_pause(this_pause)) {
assert(!G1GCPauseTypeHelper::is_concurrent_start_pause(this_pause),
@@ -889,7 +891,8 @@ void G1Policy::report_ihop_statistics() {
_ihop_control->print();
}

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

@@ -301,7 +301,8 @@ class G1Policy: public CHeapObj<mtGC> {

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

void note_gc_start();
void note_young_gc_pause_start();
void note_young_gc_pause_end();
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.

It's not obvious to me if there's a diff btw young_gc_pause and young_collection, or what the diff is. I think having some comments for these two pairs of methods would make it easier to understand.

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.

Added comments. gc_pause is the whole pause, collection is about just the collection part (as defined by the inner scope of the do_collection_pause_at_safepoint_helper). Feel free to suggest better naming.

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.

Maybe something like record_young_collection_work_start; another question is whether we should keep the note_ prefix for the pause or change it to record_ as well as it seems quite common.

Copy link
Member

@walulyai walulyai Jul 14, 2021

Choose a reason for hiding this comment

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

I suggest we change to record_


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

@@ -310,8 +311,8 @@ class G1Policy: public CHeapObj<mtGC> {
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);
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 +329,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;