Skip to content
Permalink
Browse files

Automatic merge of jdk:master into master

  • Loading branch information
duke
duke committed Jul 19, 2020
2 parents d5822e3 + 5d27067 commit fc9b9b1970fabdffb1a9e8e9ce30da1930cd99ee
@@ -252,6 +252,9 @@ void ShenandoahControlThread::run_service() {

// Commit worker statistics to cycle data
heap->phase_timings()->flush_par_workers_to_cycle();
if (ShenandoahPacing) {
heap->pacer()->flush_stats_to_cycle();
}

// Print GC stats for current cycle
{
@@ -260,6 +263,9 @@ void ShenandoahControlThread::run_service() {
ResourceMark rm;
LogStream ls(lt);
heap->phase_timings()->print_cycle_on(&ls);
if (ShenandoahPacing) {
heap->pacer()->print_cycle_on(&ls);
}
}
}

@@ -1231,13 +1231,6 @@ void ShenandoahHeap::print_tracing_info() const {

ls.cr();
ls.cr();

if (ShenandoahPacing) {
pacer()->print_on(&ls);
}

ls.cr();
ls.cr();
}
}

@@ -122,16 +122,20 @@ double HdrSeq::percentile(double level) const {

BinaryMagnitudeSeq::BinaryMagnitudeSeq() {
_mags = NEW_C_HEAP_ARRAY(size_t, BitsPerSize_t, mtInternal);
for (int c = 0; c < BitsPerSize_t; c++) {
_mags[c] = 0;
}
_sum = 0;
clear();
}

BinaryMagnitudeSeq::~BinaryMagnitudeSeq() {
FREE_C_HEAP_ARRAY(size_t, _mags);
}

void BinaryMagnitudeSeq::clear() {
for (int c = 0; c < BitsPerSize_t; c++) {
_mags[c] = 0;
}
_sum = 0;
}

void BinaryMagnitudeSeq::add(size_t val) {
Atomic::add(&_sum, val);

@@ -70,6 +70,7 @@ class BinaryMagnitudeSeq {
size_t sum() const;
int min_level() const;
int max_level() const;
void clear();
};

#endif // SHARE_GC_SHENANDOAH_SHENANDOAHNUMBERSEQ_HPP
@@ -27,6 +27,7 @@
#include "gc/shenandoah/shenandoahFreeSet.hpp"
#include "gc/shenandoah/shenandoahHeap.inline.hpp"
#include "gc/shenandoah/shenandoahPacer.hpp"
#include "gc/shenandoah/shenandoahPhaseTimings.hpp"
#include "runtime/atomic.hpp"
#include "runtime/mutexLocker.hpp"

@@ -272,7 +273,7 @@ void ShenandoahPacer::pace_for_alloc(size_t words) {
// Breaking out and allocating anyway, which may mean we outpace GC,
// and start Degenerated GC cycle.
// b) The budget had been replenished, which means our claim is satisfied.
_delays.add(total_ms);
ShenandoahThreadLocalData::add_paced_time(JavaThread::current(), end - start);
break;
}
}
@@ -294,41 +295,48 @@ void ShenandoahPacer::notify_waiters() {
}
}

void ShenandoahPacer::print_on(outputStream* out) const {
out->print_cr("ALLOCATION PACING:");
out->cr();
void ShenandoahPacer::flush_stats_to_cycle() {
double sum = 0;
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *t = jtiwh.next(); ) {
sum += ShenandoahThreadLocalData::paced_time(t);
}
ShenandoahHeap::heap()->phase_timings()->record_phase_time(ShenandoahPhaseTimings::pacing, sum);
}

out->print_cr("Max pacing delay is set for " UINTX_FORMAT " ms.", ShenandoahPacingMaxDelay);
out->cr();
void ShenandoahPacer::print_cycle_on(outputStream* out) {
MutexLocker lock(Threads_lock);

out->print_cr("Higher delay would prevent application outpacing the GC, but it will hide the GC latencies");
out->print_cr("from the STW pause times. Pacing affects the individual threads, and so it would also be");
out->print_cr("invisible to the usual profiling tools, but would add up to end-to-end application latency.");
out->print_cr("Raise max pacing delay with care.");
out->cr();
double now = os::elapsedTime();
double total = now - _last_time;
_last_time = now;

out->print_cr("Actual pacing delays histogram:");
out->cr();
out->print_cr("Allocation pacing accrued:");

size_t threads_total = 0;
size_t threads_nz = 0;
double sum = 0;
for (JavaThreadIteratorWithHandle jtiwh; JavaThread *t = jtiwh.next(); ) {
double d = ShenandoahThreadLocalData::paced_time(t);
if (d > 0) {
threads_nz++;
sum += d;
out->print_cr(" %5.0f of %5.0f ms (%5.1f%%): %s",
d * 1000, total * 1000, d/total*100, t->name());
}
threads_total++;
ShenandoahThreadLocalData::reset_paced_time(t);
}
out->print_cr(" %5.0f of %5.0f ms (%5.1f%%): <total>",
sum * 1000, total * 1000, sum/total*100);

out->print_cr("%10s - %10s %12s%12s", "From", "To", "Count", "Sum");

size_t total_count = 0;
size_t total_sum = 0;
for (int c = _delays.min_level(); c <= _delays.max_level(); c++) {
int l = (c == 0) ? 0 : 1 << (c - 1);
int r = 1 << c;
size_t count = _delays.level(c);
size_t sum = count * (r - l) / 2;
total_count += count;
total_sum += sum;

out->print_cr("%7d ms - %7d ms: " SIZE_FORMAT_W(12) SIZE_FORMAT_W(12) " ms", l, r, count, sum);
if (threads_total > 0) {
out->print_cr(" %5.0f of %5.0f ms (%5.1f%%): <average total>",
sum / threads_total * 1000, total * 1000, sum / threads_total / total * 100);
}
if (threads_nz > 0) {
out->print_cr(" %5.0f of %5.0f ms (%5.1f%%): <average non-zero>",
sum / threads_nz * 1000, total * 1000, sum / threads_nz / total * 100);
}
out->print_cr("%23s: " SIZE_FORMAT_W(12) SIZE_FORMAT_W(12) " ms", "Total", total_count, total_sum);
out->cr();
out->print_cr("Pacing delays are measured from entering the pacing code till exiting it. Therefore,");
out->print_cr("observed pacing delays may be higher than the threshold when paced thread spent more");
out->print_cr("time in the pacing code. It usually happens when thread is de-scheduled while paced,");
out->print_cr("OS takes longer to unblock the thread, or JVM experiences an STW pause.");
out->cr();
}
@@ -43,7 +43,7 @@ class ShenandoahHeap;
class ShenandoahPacer : public CHeapObj<mtGC> {
private:
ShenandoahHeap* _heap;
BinaryMagnitudeSeq _delays;
double _last_time;
TruncatedSeq* _progress_history;
Monitor* _wait_monitor;
ShenandoahSharedFlag _need_notify_waiters;
@@ -65,6 +65,7 @@ class ShenandoahPacer : public CHeapObj<mtGC> {
public:
ShenandoahPacer(ShenandoahHeap* heap) :
_heap(heap),
_last_time(os::elapsedTime()),
_progress_history(new TruncatedSeq(5)),
_wait_monitor(new Monitor(Mutex::leaf, "_wait_monitor", true, Monitor::_safepoint_check_always)),
_epoch(0),
@@ -94,7 +95,8 @@ class ShenandoahPacer : public CHeapObj<mtGC> {

intptr_t epoch();

void print_on(outputStream* out) const;
void flush_stats_to_cycle();
void print_cycle_on(outputStream* out);

private:
inline void report_internal(size_t words);
@@ -271,6 +271,17 @@ void ShenandoahPhaseTimings::print_global_on(outputStream* out) const {
out->print_cr(" all workers. Dividing the <total> over the root stage time estimates parallelism.");
out->cr();

out->print_cr(" Pacing delays are measured from entering the pacing code till exiting it. Therefore,");
out->print_cr(" observed pacing delays may be higher than the threshold when paced thread spent more");
out->print_cr(" time in the pacing code. It usually happens when thread is de-scheduled while paced,");
out->print_cr(" OS takes longer to unblock the thread, or JVM experiences an STW pause.");
out->cr();
out->print_cr(" Higher delay would prevent application outpacing the GC, but it will hide the GC latencies");
out->print_cr(" from the STW pause times. Pacing affects the individual threads, and so it would also be");
out->print_cr(" invisible to the usual profiling tools, but would add up to end-to-end application latency.");
out->print_cr(" Raise max pacing delay with care.");
out->cr();

for (uint i = 0; i < _num_phases; i++) {
if (_global_data[i].maximum() != 0) {
out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s "
@@ -163,6 +163,7 @@ class outputStream;
f(full_gc_heapdump_post, " Post Heap Dump") \
\
f(conc_uncommit, "Concurrent Uncommit") \
f(pacing, "Pacing") \
\
f(heap_iteration_roots, "Heap Iteration") \
SHENANDOAH_PAR_PHASE_DO(heap_iteration_roots_, " HI: ", f) \
@@ -49,6 +49,7 @@ class ShenandoahThreadLocalData {
uint _worker_id;
bool _force_satb_flush;
int _disarmed_value;
double _paced_time;

ShenandoahThreadLocalData() :
_gc_state(0),
@@ -59,7 +60,8 @@ class ShenandoahThreadLocalData {
_gclab_size(0),
_worker_id(INVALID_WORKER_ID),
_force_satb_flush(false),
_disarmed_value(0) {
_disarmed_value(0),
_paced_time(0) {

// At least on x86_64, nmethod entry barrier encodes _disarmed_value offset
// in instruction as disp8 immed
@@ -139,6 +141,18 @@ class ShenandoahThreadLocalData {
data(thread)->_gclab_size = v;
}

static void add_paced_time(Thread* thread, double v) {
data(thread)->_paced_time += v;
}

static double paced_time(Thread* thread) {
return data(thread)->_paced_time;
}

static void reset_paced_time(Thread* thread) {
data(thread)->_paced_time = 0;
}

static void set_disarmed_value(Thread* thread, int value) {
data(thread)->_disarmed_value = value;
}

0 comments on commit fc9b9b1

Please sign in to comment.
You can’t perform that action at this time.