Skip to content
Permalink
Browse files

8241160: Concurrent class unloading reports GCTraceTime events as JFR…

… pause sub-phase events

Reviewed-by: eosterlund, kbarrett
  • Loading branch information
stefank committed Mar 18, 2020
1 parent 4b4633d commit 16df851efd1462c957aa3bfdf0c5cc3fa3e42f67
@@ -147,7 +147,13 @@ void VM_G1Concurrent::doit() {
GCIdMark gc_id_mark(_gc_id);
GCTraceCPUTime tcpu;
G1CollectedHeap* g1h = G1CollectedHeap::heap();
GCTraceTime(Info, gc) t(_message, g1h->concurrent_mark()->gc_timer_cm(), GCCause::_no_gc, true);

// GCTraceTime(...) only supports sub-phases, so a more verbose version
// is needed when we report the top-level pause phase.
GCTraceTimeLogger(Info, gc) logger(_message, GCCause::_no_gc, true);
GCTraceTimePauseTimer timer(_message, g1h->concurrent_mark()->gc_timer_cm());
GCTraceTimeDriver t(&logger, &timer);

TraceCollectorStats tcs(g1h->g1mm()->conc_collection_counters());
SvcGCMarker sgcm(SvcGCMarker::CONCURRENT);
IsGCActiveMark x;
@@ -42,15 +42,15 @@ void GCTimer::register_gc_end(const Ticks& time) {
}

void GCTimer::register_gc_pause_start(const char* name, const Ticks& time) {
_time_partitions.report_gc_phase_start(name, time);
_time_partitions.report_gc_phase_start_top_level(name, time, GCPhase::PausePhaseType);
}

void GCTimer::register_gc_pause_end(const Ticks& time) {
_time_partitions.report_gc_phase_end(time);
}

void GCTimer::register_gc_phase_start(const char* name, const Ticks& time) {
_time_partitions.report_gc_phase_start(name, time);
_time_partitions.report_gc_phase_start_sub_phase(name, time);
}

void GCTimer::register_gc_phase_end(const Ticks& time) {
@@ -67,26 +67,12 @@ void STWGCTimer::register_gc_end(const Ticks& time) {
GCTimer::register_gc_end(time);
}

void ConcurrentGCTimer::register_gc_pause_start(const char* name, const Ticks& time) {
assert(!_is_concurrent_phase_active, "A pause phase can't be started while a concurrent phase is active.");
GCTimer::register_gc_pause_start(name, time);
}

void ConcurrentGCTimer::register_gc_pause_end(const Ticks& time) {
assert(!_is_concurrent_phase_active, "A pause phase can't be ended while a concurrent phase is active.");
GCTimer::register_gc_pause_end(time);
}

void ConcurrentGCTimer::register_gc_concurrent_start(const char* name, const Ticks& time) {
assert(!_is_concurrent_phase_active, "A concurrent phase is already active.");
_time_partitions.report_gc_phase_start(name, time, GCPhase::ConcurrentPhaseType);
_is_concurrent_phase_active = true;
_time_partitions.report_gc_phase_start_top_level(name, time, GCPhase::ConcurrentPhaseType);
}

void ConcurrentGCTimer::register_gc_concurrent_end(const Ticks& time) {
assert(_is_concurrent_phase_active, "A concurrent phase is not active.");
_time_partitions.report_gc_phase_end(time, GCPhase::ConcurrentPhaseType);
_is_concurrent_phase_active = false;
_time_partitions.report_gc_phase_end(time);
}

void PhasesStack::clear() {
@@ -111,6 +97,21 @@ int PhasesStack::count() const {
return _next_phase_level;
}

int PhasesStack::phase_index(int level) const {
assert(level < count(), "Out-of-bounds");
return _phase_indices[level];
}

GCPhase::PhaseType TimePartitions::current_phase_type() const {
int level = _active_phases.count();
assert(level > 0, "No active phase");

int index = _active_phases.phase_index(level - 1);
GCPhase phase = _phases->at(index);
GCPhase::PhaseType type = phase.type();
return type;
}

TimePartitions::TimePartitions() {
_phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<GCPhase>(INITIAL_CAPACITY, true, mtGC);
clear();
@@ -144,6 +145,23 @@ void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time,
_active_phases.push(index);
}

void TimePartitions::report_gc_phase_start_top_level(const char* name, const Ticks& time, GCPhase::PhaseType type) {
int level = _active_phases.count();
assert(level == 0, "Must be a top-level phase");

report_gc_phase_start(name, time, type);
}

void TimePartitions::report_gc_phase_start_sub_phase(const char* name, const Ticks& time) {
int level = _active_phases.count();
assert(level > 0, "Must be a sub-phase");

// Inherit phase type from parent phase.
GCPhase::PhaseType type = current_phase_type();

report_gc_phase_start(name, time, type);
}

void TimePartitions::update_statistics(GCPhase* phase) {
if ((phase->type() == GCPhase::PausePhaseType) && (phase->level() == 0)) {
const Tickspan pause = phase->end() - phase->start();
@@ -152,7 +170,7 @@ void TimePartitions::update_statistics(GCPhase* phase) {
}
}

void TimePartitions::report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type) {
void TimePartitions::report_gc_phase_end(const Ticks& time) {
int phase_index = _active_phases.pop();
GCPhase* phase = _phases->adr_at(phase_index);
phase->set_end(time);
@@ -91,9 +91,12 @@ class PhasesStack {
void push(int phase_index);
int pop();
int count() const;
int phase_index(int level) const;
};

class TimePartitions {
friend class TimePartitionsTest;

static const int INITIAL_CAPACITY = 10;

GrowableArray<GCPhase>* _phases;
@@ -102,13 +105,18 @@ class TimePartitions {
Tickspan _sum_of_pauses;
Tickspan _longest_pause;

GCPhase::PhaseType current_phase_type() const;

void report_gc_phase_start(const char* name, const Ticks& time, GCPhase::PhaseType type);

public:
TimePartitions();
~TimePartitions();
void clear();

void report_gc_phase_start(const char* name, const Ticks& time, GCPhase::PhaseType type=GCPhase::PausePhaseType);
void report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type=GCPhase::PausePhaseType);
void report_gc_phase_start_top_level(const char* name, const Ticks& time, GCPhase::PhaseType type);
void report_gc_phase_start_sub_phase(const char* name, const Ticks& time);
void report_gc_phase_end(const Ticks& time);

int num_phases() const;
GCPhase* phase_at(int index) const;
@@ -129,6 +137,7 @@ class PhasesIterator {
};

class GCTimer : public ResourceObj {
friend class GCTimerTest;
protected:
Ticks _gc_start;
Ticks _gc_end;
@@ -138,17 +147,16 @@ class GCTimer : public ResourceObj {
virtual void register_gc_start(const Ticks& time = Ticks::now());
virtual void register_gc_end(const Ticks& time = Ticks::now());

void register_gc_pause_start(const char* name, const Ticks& time = Ticks::now());
void register_gc_pause_end(const Ticks& time = Ticks::now());

void register_gc_phase_start(const char* name, const Ticks& time);
void register_gc_phase_end(const Ticks& time);

const Ticks gc_start() const { return _gc_start; }
const Ticks gc_end() const { return _gc_end; }

TimePartitions* time_partitions() { return &_time_partitions; }

protected:
void register_gc_pause_start(const char* name, const Ticks& time = Ticks::now());
void register_gc_pause_end(const Ticks& time = Ticks::now());
};

class STWGCTimer : public GCTimer {
@@ -158,16 +166,7 @@ class STWGCTimer : public GCTimer {
};

class ConcurrentGCTimer : public GCTimer {
// ConcurrentGCTimer can't be used if there is an overlap between a pause phase and a concurrent phase.
// _is_concurrent_phase_active is used to find above case.
bool _is_concurrent_phase_active;

public:
ConcurrentGCTimer(): GCTimer(), _is_concurrent_phase_active(false) {};

void register_gc_pause_start(const char* name, const Ticks& time = Ticks::now());
void register_gc_pause_end(const Ticks& time = Ticks::now());

void register_gc_concurrent_start(const char* name, const Ticks& time = Ticks::now());
void register_gc_concurrent_end(const Ticks& time = Ticks::now());
};
@@ -303,10 +303,11 @@ class PhaseSender : public PhaseVisitor {
}

void visit_concurrent(GCPhase* phase) {
assert(phase->level() < 1, "There is only one level for ConcurrentPhase");
assert(phase->level() < 2, "There is only two levels for ConcurrentPhase");

switch (phase->level()) {
case 0: send_phase<EventGCPhaseConcurrent>(phase); break;
case 1: send_phase<EventGCPhaseConcurrentLevel1>(phase); break;
default: /* Ignore sending this phase */ break;
}
}
@@ -23,10 +23,53 @@
*/

#include "precompiled.hpp"
#include "gc/shared/collectedHeap.hpp"
#include "gc/shared/gcTraceTime.inline.hpp"
#include "logging/log.hpp"
#include "logging/logStream.hpp"
#include "memory/universe.hpp"
#include "runtime/os.hpp"

void GCTraceTimeLoggerImpl::log_start(Ticks start) {
_start = start;

LogStream out(_out_start);

out.print("%s", _title);
if (_gc_cause != GCCause::_no_gc) {
out.print(" (%s)", GCCause::to_string(_gc_cause));
}
out.cr();

if (_log_heap_usage) {
_heap_usage_before = Universe::heap()->used();
}
}

void GCTraceTimeLoggerImpl::log_end(Ticks end) {
double duration_in_ms = TimeHelper::counter_to_millis(end.value() - _start.value());
double start_time_in_secs = TimeHelper::counter_to_seconds(_start.value());
double stop_time_in_secs = TimeHelper::counter_to_seconds(end.value());

LogStream out(_out_end);

out.print("%s", _title);

if (_gc_cause != GCCause::_no_gc) {
out.print(" (%s)", GCCause::to_string(_gc_cause));
}

if (_heap_usage_before != SIZE_MAX) {
CollectedHeap* heap = Universe::heap();
size_t used_before_m = _heap_usage_before / M;
size_t used_m = heap->used() / M;
size_t capacity_m = heap->capacity() / M;
out.print(" " SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)", used_before_m, used_m, capacity_m);
}

out.print_cr(" %.3fms", duration_in_ms);
}

GCTraceCPUTime::GCTraceCPUTime() :
_active(log_is_enabled(Info, gc, cpu)),
_starting_user_time(0.0),

0 comments on commit 16df851

Please sign in to comment.