8241160: Concurrent class unloading reports GCTraceTime events as JFR pause sub-phase events

Reviewed-by: eosterlund, kbarrett
This commit is contained in:
Stefan Karlsson 2020-03-18 17:28:41 +01:00
parent 4b4633d976
commit 16df851efd
14 changed files with 542 additions and 234 deletions

@ -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,7 +42,7 @@ 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) {
@ -50,7 +50,7 @@ void GCTimer::register_gc_pause_end(const Ticks& 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,6 +147,9 @@ 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);
@ -145,10 +157,6 @@ class GCTimer : public ResourceObj {
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),

@ -25,6 +25,7 @@
#ifndef SHARE_GC_SHARED_GCTRACETIME_HPP
#define SHARE_GC_SHARED_GCTRACETIME_HPP
#include "gc/shared/gcCause.hpp"
#include "logging/log.hpp"
#include "logging/logHandle.hpp"
#include "logging/logStream.hpp"
@ -43,32 +44,112 @@ class GCTraceCPUTime : public StackObj {
class GCTimer;
class GCTraceTimeImpl : public StackObj {
private:
LogTargetHandle _out_start;
LogTargetHandle _out_stop;
bool _enabled;
Ticks _start_ticks;
const char* _title;
GCCause::Cause _gc_cause;
GCTimer* _timer;
size_t _heap_usage_before;
void log_start(jlong start_counter);
void log_stop(jlong start_counter, jlong stop_counter);
void time_stamp(Ticks& ticks);
public:
GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_end, const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false);
~GCTraceTimeImpl();
// Callback to be invoked when the
// GCTraceTimer goes in and out of scope.
class TimespanCallback {
public:
virtual void at_start(Ticks start) = 0;
virtual void at_end(Ticks end) = 0;
};
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
class GCTraceTimeImplWrapper : public StackObj {
GCTraceTimeImpl _impl;
// Class used by the GCTraceTimer to to feed start and end ticks
// when it goes in and out of scope. All callbacks get the same
// start and end ticks.
//
// Example of callbacks:
// Logging to unified loggingUnified Logging logger
// Registering GCTimer phases
class GCTraceTimeDriver : public StackObj {
private:
// An arbitrary number of callbacks - extend if needed
TimespanCallback* _cb0;
TimespanCallback* _cb1;
TimespanCallback* _cb2;
bool has_callbacks() const;
void at_start(TimespanCallback* cb, Ticks start);
void at_end(TimespanCallback* cb, Ticks end);
public:
GCTraceTimeDriver(TimespanCallback* cb0 = NULL,
TimespanCallback* cb1 = NULL,
TimespanCallback* cb2 = NULL);
~GCTraceTimeDriver();
};
// Implements the ordinary logging part of the GCTraceTimer.
class GCTraceTimeLoggerImpl : public TimespanCallback {
const bool _enabled;
const char* const _title;
const GCCause::Cause _gc_cause;
const bool _log_heap_usage;
const LogTargetHandle _out_start;
const LogTargetHandle _out_end;
size_t _heap_usage_before;
Ticks _start;
void log_start(Ticks start);
void log_end(Ticks end);
public:
GCTraceTimeImplWrapper(const char* title, GCTimer* timer = NULL, GCCause::Cause gc_cause = GCCause::_no_gc, bool log_heap_usage = false);
~GCTraceTimeImplWrapper();
GCTraceTimeLoggerImpl(const char* title,
GCCause::Cause gc_cause,
bool log_heap_usage,
LogTargetHandle out_start,
LogTargetHandle out_end);
virtual void at_start(Ticks start);
virtual void at_end(Ticks end);
bool is_enabled() const;
};
// Implements the GCTimer phase registration. Can be used when
// GCTraceTime is used to register a sub-phase. The super-phase
// determines the type (Pause or Concurrent).
class GCTraceTimeTimer : public TimespanCallback {
const char* const _title;
GCTimer* const _timer;
public:
GCTraceTimeTimer(const char* title, GCTimer* timer);
virtual void at_start(Ticks start);
virtual void at_end(Ticks end);
};
// Implements GCTimer pause registration. Can be used
// when the GCTraceTimer is used to report the top-level
// pause phase.
class GCTraceTimePauseTimer : public TimespanCallback {
const char* const _title;
GCTimer* const _timer;
public:
GCTraceTimePauseTimer(const char* title, GCTimer* timer);
virtual void at_start(Ticks start);
virtual void at_end(Ticks end);
};
// The GCTraceTime implementation class.It creates the normal
// set of callbacks and installs them into the driver. When the
// constructor is run the callbacks get the at_start call, and
// when the destructor is run the callbacks get the at_end call.
class GCTraceTimeImpl : public StackObj {
GCTraceTimeLoggerImpl _logger;
GCTraceTimeTimer _timer;
GCTraceTimeDriver _driver;
public:
GCTraceTimeImpl(const char* title,
LogTargetHandle out_start,
LogTargetHandle out_end,
GCTimer* timer,
GCCause::Cause gc_cause,
bool log_heap_usage);
};
// Similar to GCTraceTimeImpl but is intended for concurrent phase logging,

@ -25,92 +25,181 @@
#ifndef SHARE_GC_SHARED_GCTRACETIME_INLINE_HPP
#define SHARE_GC_SHARED_GCTRACETIME_INLINE_HPP
#include "gc/shared/collectedHeap.hpp"
#include "gc/shared/gcTimer.hpp"
#include "gc/shared/gcTrace.hpp"
#include "gc/shared/gcTraceTime.hpp"
#include "logging/log.hpp"
#include "logging/logStream.hpp"
#include "memory/universe.hpp"
#include "utilities/ticks.hpp"
#define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
inline GCTraceTimeDriver::GCTraceTimeDriver(
TimespanCallback* cb0,
TimespanCallback* cb1,
TimespanCallback* cb2) :
_cb0(cb0),
_cb1(cb1),
_cb2(cb2) {
inline void GCTraceTimeImpl::log_start(jlong start_counter) {
if (_out_start.is_enabled()) {
LogStream out(_out_start);
Ticks start;
out.print("%s", _title);
if (_gc_cause != GCCause::_no_gc) {
out.print(" (%s)", GCCause::to_string(_gc_cause));
}
out.cr();
if (has_callbacks()) {
start.stamp();
}
at_start(_cb0, start);
at_start(_cb1, start);
at_start(_cb2, start);
}
inline GCTraceTimeDriver::~GCTraceTimeDriver() {
Ticks end;
if (has_callbacks()) {
end.stamp();
}
at_end(_cb0, end);
at_end(_cb1, end);
at_end(_cb2, end);
}
inline bool GCTraceTimeDriver::has_callbacks() const {
return _cb0 != NULL || _cb1 != NULL || _cb2 != NULL;
}
inline void GCTraceTimeDriver::at_start(TimespanCallback* cb, Ticks start) {
if (cb != NULL) {
cb->at_start(start);
}
}
inline void GCTraceTimeImpl::log_stop(jlong start_counter, jlong stop_counter) {
double duration_in_ms = TimeHelper::counter_to_millis(stop_counter - start_counter);
double start_time_in_secs = TimeHelper::counter_to_seconds(start_counter);
double stop_time_in_secs = TimeHelper::counter_to_seconds(stop_counter);
LogStream out(_out_stop);
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(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m);
}
out.print_cr(" %.3fms", duration_in_ms);
}
inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) {
if (_enabled || _timer != NULL) {
ticks.stamp();
inline void GCTraceTimeDriver::at_end(TimespanCallback* cb, Ticks end) {
if (cb != NULL) {
cb->at_end(end);
}
}
inline GCTraceTimeImpl::GCTraceTimeImpl(LogTargetHandle out_start, LogTargetHandle out_stop, const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage) :
_out_start(out_start),
_out_stop(out_stop),
_enabled(out_stop.is_enabled()),
_start_ticks(),
_title(title),
_gc_cause(gc_cause),
_timer(timer),
_heap_usage_before(SIZE_MAX) {
inline GCTraceTimeLoggerImpl::GCTraceTimeLoggerImpl(
const char* title,
GCCause::Cause gc_cause,
bool log_heap_usage,
LogTargetHandle out_start,
LogTargetHandle out_end) :
_enabled(out_end.is_enabled()),
_title(title),
_gc_cause(gc_cause),
_log_heap_usage(log_heap_usage),
_out_start(out_start),
_out_end(out_end),
_heap_usage_before(SIZE_MAX),
_start() {}
time_stamp(_start_ticks);
inline void GCTraceTimeLoggerImpl::at_start(Ticks start) {
if (_enabled) {
if (log_heap_usage) {
_heap_usage_before = Universe::heap()->used();
}
log_start(_start_ticks.value());
}
if (_timer != NULL) {
_timer->register_gc_phase_start(_title, _start_ticks);
log_start(start);
}
}
inline GCTraceTimeImpl::~GCTraceTimeImpl() {
Ticks stop_ticks;
time_stamp(stop_ticks);
inline void GCTraceTimeLoggerImpl::at_end(Ticks end) {
if (_enabled) {
log_stop(_start_ticks.value(), stop_ticks.value());
}
if (_timer != NULL) {
_timer->register_gc_phase_end(stop_ticks);
log_end(end);
}
}
inline bool GCTraceTimeLoggerImpl::is_enabled() const {
return _enabled;
}
inline GCTraceTimeTimer::GCTraceTimeTimer(const char* title, GCTimer* timer) : _title(title), _timer(timer) {}
inline void GCTraceTimeTimer::at_start(Ticks start) {
if (_timer != NULL) {
_timer->register_gc_phase_start(_title, start);
}
}
inline void GCTraceTimeTimer::at_end(Ticks end) {
if (_timer != NULL) {
_timer->register_gc_phase_end(end);
}
}
inline GCTraceTimePauseTimer::GCTraceTimePauseTimer(const char* title, GCTimer* timer) : _title(title), _timer(timer) {}
inline void GCTraceTimePauseTimer::at_start(Ticks start) {
if (_timer != NULL) {
_timer->register_gc_pause_start(_title, start);
}
}
inline void GCTraceTimePauseTimer::at_end(Ticks end) {
if (_timer != NULL) {
_timer->register_gc_pause_end(end);
}
}
inline GCTraceTimeImpl::GCTraceTimeImpl(
const char* title,
LogTargetHandle out_start,
LogTargetHandle out_end,
GCTimer* timer,
GCCause::Cause gc_cause,
bool log_heap_usage) :
_logger(title,
gc_cause,
log_heap_usage,
out_start,
out_end),
_timer(title, timer),
// Only register the callbacks if they are enabled
_driver((_logger.is_enabled() ? &_logger : NULL),
(timer != NULL ? &_timer : NULL)) {}
// Figure out the first __NO_TAG position and replace it with 'start'.
#define INJECT_START_TAG(T1, T2, T3, T4) \
(( T1 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T1), \
((T1 != LogTag::__NO_TAG && T2 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T2), \
((T2 != LogTag::__NO_TAG && T3 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T3), \
((T3 != LogTag::__NO_TAG && T4 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T4)
// Shim to convert LogTag templates to LogTargetHandle
template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
class GCTraceTimeLoggerWrapper : public GCTraceTimeLoggerImpl {
public:
GCTraceTimeLoggerWrapper(const char* title, GCCause::Cause gc_cause, bool log_heap_usage) :
GCTraceTimeLoggerImpl(
title,
gc_cause,
log_heap_usage,
LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(),
LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>()) {
STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
}
};
// Shim to convert LogTag templates to LogTargetHandle
template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
class GCTraceTimeWrapper : public StackObj {
GCTraceTimeImpl _impl;
public:
GCTraceTimeWrapper(
const char* title,
GCTimer* timer = NULL,
GCCause::Cause gc_cause = GCCause::_no_gc,
bool log_heap_usage = false) :
_impl(title,
LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(),
LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(),
timer,
gc_cause,
log_heap_usage) {
STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
}
};
#undef INJECT_START_TAG
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag >
GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) :
_enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
@ -128,34 +217,29 @@ GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl()
}
}
// Figure out the first __NO_TAG position and replace it with 'start'.
#define INJECT_START_TAG(T1, T2, T3, T4) \
(( T1 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T1), \
((T1 != LogTag::__NO_TAG && T2 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T2), \
((T2 != LogTag::__NO_TAG && T3 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T3), \
((T3 != LogTag::__NO_TAG && T4 == LogTag::__NO_TAG) ? PREFIX_LOG_TAG(start) : T4)
// Helper macros to support the usual use-cases.
template <LogLevelType level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
GCTraceTimeImplWrapper<level, T0, T1, T2, T3, T4, GuardTag>::GCTraceTimeImplWrapper(
const char* title, GCTimer* timer, GCCause::Cause gc_cause, bool log_heap_usage)
: _impl(
LogTargetHandle::create<level, T0, INJECT_START_TAG(T1, T2, T3, T4), GuardTag>(),
LogTargetHandle::create<level, T0, T1, T2, T3, T4, GuardTag>(),
title,
timer,
gc_cause,
log_heap_usage) {
// This is the main macro used by most GCTraceTime users.
//
// Examples:
// GCTraceTime(Info, gc, phase) t("The sub-phase name");
// Log to unified logging on gc+phase=info level.
//
// GCTraceTime(Info, gc, phase) t("The sub-phase name", timer);
// Same as above but also register the times in the GCTimer timer.
//
// See GCTraceTimeWrapper for the available parameters.
#define GCTraceTime(Level, ...) GCTraceTimeWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
STATIC_ASSERT(T0 != LogTag::__NO_TAG); // Need some tag to log on.
STATIC_ASSERT(T4 == LogTag::__NO_TAG); // Need to leave at least the last tag for the "start" tag in log_start()
}
// The vanilla GCTraceTime macro doesn't cater to all use-cases.
// This macro allows the users to create the unified logging callback.
//
// Example:
// GCTraceTimeLogger(Info, gc) logger(_message, GCCause::_no_gc, true);
// GCTraceTimePauseTimer timer(_message, g1h->concurrent_mark()->gc_timer_cm());
// GCTraceTimeDriver t(&logger, &timer);
#define GCTraceTimeLogger(Level, ...) GCTraceTimeLoggerWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
#undef INJECT_START_TAG
template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTagType T3, LogTagType T4, LogTagType GuardTag>
GCTraceTimeImplWrapper<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceTimeImplWrapper() {}
#define GCTraceTime(Level, ...) GCTraceTimeImplWrapper<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
#define GCTraceConcTime(Level, ...) GCTraceConcTimeImpl<LogLevel::Level, LOG_TAGS(__VA_ARGS__)>
#endif // SHARE_GC_SHARED_GCTRACETIME_INLINE_HPP

@ -140,7 +140,7 @@ void ShenandoahUnload::unlink() {
ShenandoahHeap* const heap = ShenandoahHeap::heap();
{
MutexLocker cldg_ml(ClassLoaderDataGraph_lock);
unloading_occurred = SystemDictionary::do_unloading(heap->gc_timer());
unloading_occurred = SystemDictionary::do_unloading(NULL /* gc_timer */);
}
Klass::clean_weak_klass_links(unloading_occurred);

@ -77,7 +77,7 @@ ShenandoahGCPauseMark::ShenandoahGCPauseMark(uint gc_id, SvcGCMarker::reason_typ
// FIXME: It seems that JMC throws away level 0 events, which are the Shenandoah
// pause events. Create this pseudo level 0 event to push real events to level 1.
_heap->gc_timer()->register_gc_phase_start("Shenandoah", Ticks::now());
_heap->gc_timer()->register_gc_pause_start("Shenandoah", Ticks::now());
_trace_pause.initialize(_heap->stw_memory_manager(), _heap->gc_cause(),
/* allMemoryPoolsAffected */ true,
/* recordGCBeginTime = */ true,
@ -93,7 +93,7 @@ ShenandoahGCPauseMark::ShenandoahGCPauseMark(uint gc_id, SvcGCMarker::reason_typ
}
ShenandoahGCPauseMark::~ShenandoahGCPauseMark() {
_heap->gc_timer()->register_gc_phase_end(Ticks::now());
_heap->gc_timer()->register_gc_pause_end(Ticks::now());
_heap->heuristics()->record_gc_end();
}

@ -453,6 +453,11 @@
<Field type="string" name="name" label="Name" />
</Event>
<Event name="GCPhaseConcurrentLevel1" category="Java Virtual Machine, GC, Phases" label="GC Phase Concurrent Level 1" thread="true">
<Field type="uint" name="gcId" label="GC Identifier" relation="GcId" />
<Field type="string" name="name" label="Name" />
</Event>
<Event name="GCPhaseParallel" category="Java Virtual Machine, GC, Phases" label="GC Phase Parallel"
startTime="true" thread="true" description="GC phases for parallel workers">
<Field type="uint" name="gcId" label="GC Identifier" relation="GcId"/>

@ -235,7 +235,7 @@ class TimeInstant : public Rep<TimeSource> {
friend class ObjectSample;
friend class EventEmitter;
// GC unit tests
friend class TimePartitionPhasesIteratorTest;
friend class TimePartitionsTest;
friend class GCTimerTest;
friend class CompilerEvent;
};

@ -391,6 +391,11 @@
<setting name="threshold">0 ms</setting>
</event>
<event name="jdk.GCPhaseConcurrentLevel1">
<setting name="enabled" control="gc-enabled-all">true</setting>
<setting name="threshold">0 ms</setting>
</event>
<event name="jdk.GCReferenceStatistics">
<setting name="enabled" control="gc-enabled-normal">true</setting>
</event>

@ -391,6 +391,11 @@
<setting name="threshold">0 ms</setting>
</event>
<event name="jdk.GCPhaseConcurrentLevel1">
<setting name="enabled" control="gc-enabled-all">true</setting>
<setting name="threshold">0 ms</setting>
</event>
<event name="jdk.GCReferenceStatistics">
<setting name="enabled" control="gc-enabled-normal">true</setting>
</event>

@ -34,8 +34,24 @@ class GCTimerTest {
static void register_gc_end(GCTimer* const timer, jlong ticks) {
timer->register_gc_end(Ticks(ticks));
}
static void register_gc_pause_start(GCTimer* const timer, jlong ticks) {
timer->register_gc_pause_start("pause", Ticks(ticks));
}
static void register_gc_pause_end(GCTimer* const timer, jlong ticks) {
timer->register_gc_pause_end(Ticks(ticks));
}
static void register_gc_concurrent_start(ConcurrentGCTimer* const timer, jlong ticks) {
timer->register_gc_concurrent_start("concurrent", Ticks(ticks));
}
static void register_gc_concurrent_end(ConcurrentGCTimer* const timer, jlong ticks) {
timer->register_gc_concurrent_end(Ticks(ticks));
}
static Tickspan duration(jlong ticks) { return Ticks(ticks) - Ticks(0); }
};
static Tickspan duration(jlong ticks) { return GCTimerTest::duration(ticks); }
TEST(GCTimer, start) {
GCTimer gc_timer;
GCTimerTest::register_gc_start(&gc_timer, 1);
@ -52,7 +68,52 @@ TEST(GCTimer, end) {
EXPECT_EQ(2, gc_timer.gc_end().value());
}
class TimePartitionPhasesIteratorTest {
TEST(GCTimer, pause) {
GCTimer gc_timer;
GCTimerTest::register_gc_start(&gc_timer, 1);
GCTimerTest::register_gc_pause_start(&gc_timer, 2);
GCTimerTest::register_gc_pause_end(&gc_timer, 4);
GCTimerTest::register_gc_end(&gc_timer, 5);
TimePartitions* partitions = gc_timer.time_partitions();
EXPECT_EQ(1, partitions->num_phases());
EXPECT_EQ(duration(2), partitions->sum_of_pauses());
EXPECT_EQ(5, gc_timer.gc_end().value());
}
TEST(ConcurrentGCTimer, pause) {
ConcurrentGCTimer gc_timer;
GCTimerTest::register_gc_start(&gc_timer, 1);
GCTimerTest::register_gc_pause_start(&gc_timer, 2);
GCTimerTest::register_gc_pause_end(&gc_timer, 4);
GCTimerTest::register_gc_end(&gc_timer, 7);
TimePartitions* partitions = gc_timer.time_partitions();
EXPECT_EQ(1, partitions->num_phases());
EXPECT_EQ(duration(2), partitions->sum_of_pauses());
EXPECT_EQ(7, gc_timer.gc_end().value());
}
TEST(ConcurrentGCTimer, concurrent) {
ConcurrentGCTimer gc_timer;
GCTimerTest::register_gc_start(&gc_timer, 1);
GCTimerTest::register_gc_concurrent_start(&gc_timer, 2);
GCTimerTest::register_gc_concurrent_end(&gc_timer, 4);
GCTimerTest::register_gc_end(&gc_timer, 5);
TimePartitions* partitions = gc_timer.time_partitions();
EXPECT_EQ(1, partitions->num_phases());
EXPECT_EQ(duration(0), partitions->sum_of_pauses());
EXPECT_EQ(5, gc_timer.gc_end().value());
}
class TimePartitionsTest {
public:
static void validate_gc_phase(GCPhase* phase, int level, const char* name, const jlong& start, const jlong& end) {
@ -67,172 +128,172 @@ class TimePartitionPhasesIteratorTest {
EXPECT_EQ(expected_longest_pause, time_partitions.longest_pause());
}
static void validate_pauses(const TimePartitions& time_partitions, const Tickspan& expected_pause) {
TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, expected_pause, expected_pause);
validate_pauses(time_partitions, expected_pause, expected_pause);
}
static void validate_pauses(const TimePartitions& time_partitions, jlong end, jlong start) {
TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, Ticks(end) - Ticks(start));
validate_pauses(time_partitions, Ticks(end) - Ticks(start));
}
static void validate_pauses(const TimePartitions& time_partitions, jlong all_end, jlong all_start, jlong longest_end, jlong longest_start) {
TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, Ticks(all_end) - Ticks(all_start), Ticks(longest_end) - Ticks(longest_start));
validate_pauses(time_partitions, Ticks(all_end) - Ticks(all_start), Ticks(longest_end) - Ticks(longest_start));
}
static void report_gc_phase_start(TimePartitions* const partitions, const char* name, jlong ticks, GCPhase::PhaseType type=GCPhase::PausePhaseType) {
partitions->report_gc_phase_start(name, Ticks(ticks), type);
}
static void report_gc_phase_end(TimePartitions* const partitions, jlong ticks, GCPhase::PhaseType type=GCPhase::PausePhaseType) {
partitions->report_gc_phase_end(Ticks(ticks), type);
static void report_gc_phase_end(TimePartitions* const partitions, jlong ticks) {
partitions->report_gc_phase_end(Ticks(ticks));
}
};
TEST(TimePartitionPhasesIterator, one_pause) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 8, 2));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 8, 2));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, two_pauses) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase1", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 3);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase2", 4);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase1", 2);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 3);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase2", 4);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase1", 2, 3));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase2", 4, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase1", 2, 3));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase2", 4, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 3, 0, 2, 0));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 3, 0, 2, 0));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, one_sub_pause_phase) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase", 3);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 4);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 5);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase", 3);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 4);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 5);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 5));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase", 3, 4));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 5));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase", 3, 4));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 3, 0));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 3, 0));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, max_nested_pause_phases) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase2", 4);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase3", 5);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 7);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 9);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase2", 4);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase3", 5);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 7);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 9);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 9));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 2, "SubPhase2", 4, 7));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 3, "SubPhase3", 5, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 9));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 2, "SubPhase2", 4, 7));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 3, "SubPhase3", 5, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 7, 0));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 7, 0));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, many_sub_pause_phases) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 4);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase2", 5);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase3", 7);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase4", 9);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 10);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 4);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase2", 5);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 6);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase3", 7);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase4", 9);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 10);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 11);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 11);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 11));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 4));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase2", 5, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase3", 7, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase4", 9, 10));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 11));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 4));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase2", 5, 6));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase3", 7, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase4", 9, 10));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 9, 0));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 9, 0));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, many_sub_pause_phases2) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "PausePhase", 2);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase11", 4);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 5);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase12", 6);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 7);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase1", 3);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase11", 4);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 5);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase12", 6);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 7);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase2", 9);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase21", 10);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 11);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase22", 12);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 13);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 14);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase2", 9);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase21", 10);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 11);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase22", 12);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 13);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 14);
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "SubPhase3", 15);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 16);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "SubPhase3", 15);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 16);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 17);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 17);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 17));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 2, "SubPhase11", 4, 5));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 2, "SubPhase12", 6, 7));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase2", 9, 14));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 2, "SubPhase21", 10, 11));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 2, "SubPhase22", 12, 13));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 1, "SubPhase3", 15, 16));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "PausePhase", 2, 17));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 2, "SubPhase11", 4, 5));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 2, "SubPhase12", 6, 7));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase2", 9, 14));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 2, "SubPhase21", 10, 11));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 2, "SubPhase22", 12, 13));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 1, "SubPhase3", 15, 16));
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, 15, 0));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, 15, 0));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}
TEST(TimePartitionPhasesIterator, one_concurrent) {
TimePartitions time_partitions;
TimePartitionPhasesIteratorTest::report_gc_phase_start(&time_partitions, "ConcurrentPhase", 2, GCPhase::ConcurrentPhaseType);
TimePartitionPhasesIteratorTest::report_gc_phase_end(&time_partitions, 8, GCPhase::ConcurrentPhaseType);
TimePartitionsTest::report_gc_phase_start(&time_partitions, "ConcurrentPhase", 2, GCPhase::ConcurrentPhaseType);
TimePartitionsTest::report_gc_phase_end(&time_partitions, 8);
TimePartitionPhasesIterator iter(&time_partitions);
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_gc_phase(iter.next(), 0, "ConcurrentPhase", 2, 8));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_gc_phase(iter.next(), 0, "ConcurrentPhase", 2, 8));
// ConcurrentPhaseType should not affect to both 'sum_of_pauses()' and 'longest_pause()'.
EXPECT_NO_FATAL_FAILURE(TimePartitionPhasesIteratorTest::validate_pauses(time_partitions, Tickspan()));
EXPECT_NO_FATAL_FAILURE(TimePartitionsTest::validate_pauses(time_partitions, Tickspan()));
EXPECT_FALSE(iter.has_next()) << "Too many elements";
}