sla@5237: /*
sla@5237:  * Copyright (c) 2012, 2013, Oracle and/or its affiliates. All rights reserved.
sla@5237:  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
sla@5237:  *
sla@5237:  * This code is free software; you can redistribute it and/or modify it
sla@5237:  * under the terms of the GNU General Public License version 2 only, as
sla@5237:  * published by the Free Software Foundation.
sla@5237:  *
sla@5237:  * This code is distributed in the hope that it will be useful, but WITHOUT
sla@5237:  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
sla@5237:  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
sla@5237:  * version 2 for more details (a copy is included in the LICENSE file that
sla@5237:  * accompanied this code).
sla@5237:  *
sla@5237:  * You should have received a copy of the GNU General Public License version
sla@5237:  * 2 along with this work; if not, write to the Free Software Foundation,
sla@5237:  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
sla@5237:  *
sla@5237:  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
sla@5237:  * or visit www.oracle.com if you need additional information or have any
sla@5237:  * questions.
sla@5237:  *
sla@5237:  */
sla@5237: 
sla@5237: #include "precompiled.hpp"
sla@5237: #include "gc_implementation/shared/gcTimer.hpp"
sla@5237: #include "utilities/growableArray.hpp"
mgronlun@6131: #include "utilities/ticks.inline.hpp"
sla@5237: 
mgronlun@6131: // the "time" parameter for most functions
mgronlun@6131: // has a default value set by Ticks::now()
mgronlun@6131: 
mgronlun@6131: void GCTimer::register_gc_start(const Ticks& time) {
sla@5237:   _time_partitions.clear();
sla@5237:   _gc_start = time;
sla@5237: }
sla@5237: 
mgronlun@6131: void GCTimer::register_gc_end(const Ticks& time) {
sla@5237:   assert(!_time_partitions.has_active_phases(),
sla@5237:       "We should have ended all started phases, before ending the GC");
sla@5237: 
sla@5237:   _gc_end = time;
sla@5237: }
sla@5237: 
mgronlun@6131: void GCTimer::register_gc_pause_start(const char* name, const Ticks& time) {
sla@5237:   _time_partitions.report_gc_phase_start(name, time);
sla@5237: }
sla@5237: 
mgronlun@6131: void GCTimer::register_gc_pause_end(const Ticks& time) {
sla@5237:   _time_partitions.report_gc_phase_end(time);
sla@5237: }
sla@5237: 
mgronlun@6131: void GCTimer::register_gc_phase_start(const char* name, const Ticks& time) {
sla@5237:   _time_partitions.report_gc_phase_start(name, time);
sla@5237: }
sla@5237: 
mgronlun@6131: void GCTimer::register_gc_phase_end(const Ticks& time) {
sla@5237:   _time_partitions.report_gc_phase_end(time);
sla@5237: }
sla@5237: 
mgronlun@6131: void STWGCTimer::register_gc_start(const Ticks& time) {
sla@5237:   GCTimer::register_gc_start(time);
sla@5237:   register_gc_pause_start("GC Pause", time);
sla@5237: }
sla@5237: 
mgronlun@6131: void STWGCTimer::register_gc_end(const Ticks& time) {
sla@5237:   register_gc_pause_end(time);
sla@5237:   GCTimer::register_gc_end(time);
sla@5237: }
sla@5237: 
mgronlun@6131: void ConcurrentGCTimer::register_gc_pause_start(const char* name) {
mgronlun@6131:   GCTimer::register_gc_pause_start(name);
sla@5237: }
sla@5237: 
mgronlun@6131: void ConcurrentGCTimer::register_gc_pause_end() {
mgronlun@6131:   GCTimer::register_gc_pause_end();
sla@5237: }
sla@5237: 
sla@5237: void PhasesStack::clear() {
sla@5237:   _next_phase_level = 0;
sla@5237: }
sla@5237: 
sla@5237: void PhasesStack::push(int phase_index) {
sla@5237:   assert(_next_phase_level < PHASE_LEVELS, "Overflow");
sla@5237: 
sla@5237:   _phase_indices[_next_phase_level] = phase_index;
sla@5237: 
sla@5237:   _next_phase_level++;
sla@5237: }
sla@5237: 
sla@5237: int PhasesStack::pop() {
sla@5237:   assert(_next_phase_level > 0, "Underflow");
sla@5237: 
sla@5237:   _next_phase_level--;
sla@5237: 
sla@5237:   return _phase_indices[_next_phase_level];
sla@5237: }
sla@5237: 
sla@5237: int PhasesStack::count() const {
sla@5237:   return _next_phase_level;
sla@5237: }
sla@5237: 
sla@5237: 
sla@5237: TimePartitions::TimePartitions() {
sla@5237:   _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<PausePhase>(INITIAL_CAPACITY, true, mtGC);
sla@5237:   clear();
sla@5237: }
sla@5237: 
sla@5237: TimePartitions::~TimePartitions() {
sla@5237:   delete _phases;
sla@5237:   _phases = NULL;
sla@5237: }
sla@5237: 
sla@5237: void TimePartitions::clear() {
sla@5237:   _phases->clear();
sla@5237:   _active_phases.clear();
mgronlun@6131:   _sum_of_pauses = Tickspan();
mgronlun@6131:   _longest_pause = Tickspan();
sla@5237: }
sla@5237: 
mgronlun@6131: void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time) {
sla@5237:   assert(_phases->length() <= 1000, "Too many recored phases?");
sla@5237: 
sla@5237:   int level = _active_phases.count();
sla@5237: 
sla@5237:   PausePhase phase;
sla@5237:   phase.set_level(level);
sla@5237:   phase.set_name(name);
sla@5237:   phase.set_start(time);
sla@5237: 
sla@5237:   int index = _phases->append(phase);
sla@5237: 
sla@5237:   _active_phases.push(index);
sla@5237: }
sla@5237: 
sla@5237: void TimePartitions::update_statistics(GCPhase* phase) {
sla@5237:   // FIXME: This should only be done for pause phases
sla@5237:   if (phase->level() == 0) {
mgronlun@6131:     const Tickspan pause = phase->end() - phase->start();
sla@5237:     _sum_of_pauses += pause;
sla@5237:     _longest_pause = MAX2(pause, _longest_pause);
sla@5237:   }
sla@5237: }
sla@5237: 
mgronlun@6131: void TimePartitions::report_gc_phase_end(const Ticks& time) {
sla@5237:   int phase_index = _active_phases.pop();
sla@5237:   GCPhase* phase = _phases->adr_at(phase_index);
sla@5237:   phase->set_end(time);
sla@5237:   update_statistics(phase);
sla@5237: }
sla@5237: 
sla@5237: int TimePartitions::num_phases() const {
sla@5237:   return _phases->length();
sla@5237: }
sla@5237: 
sla@5237: GCPhase* TimePartitions::phase_at(int index) const {
sla@5237:   assert(index >= 0, "Out of bounds");
sla@5237:   assert(index < _phases->length(), "Out of bounds");
sla@5237: 
sla@5237:   return _phases->adr_at(index);
sla@5237: }
sla@5237: 
sla@5237: bool TimePartitions::has_active_phases() {
sla@5237:   return _active_phases.count() > 0;
sla@5237: }
sla@5237: 
sla@5237: bool TimePartitionPhasesIterator::has_next() {
sla@5237:   return _next < _time_partitions->num_phases();
sla@5237: }
sla@5237: 
sla@5237: GCPhase* TimePartitionPhasesIterator::next() {
sla@5237:   assert(has_next(), "Must have phases left");
sla@5237:   return _time_partitions->phase_at(_next++);
sla@5237: }
sla@5237: 
sla@5237: 
sla@5237: /////////////// Unit tests ///////////////
sla@5237: 
sla@5237: #ifndef PRODUCT
sla@5237: 
sla@5237: class TimePartitionPhasesIteratorTest {
sla@5237:  public:
sla@5237:   static void all() {
sla@5237:     one_pause();
sla@5237:     two_pauses();
sla@5237:     one_sub_pause_phase();
sla@5237:     many_sub_pause_phases();
sla@5237:     many_sub_pause_phases2();
sla@5237:     max_nested_pause_phases();
sla@5237:   }
sla@5237: 
mgronlun@6131:   static void validate_pause_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {
sla@5237:     assert(phase->level() == level, "Incorrect level");
sla@5237:     assert(strcmp(phase->name(), name) == 0, "Incorrect name");
sla@5237:     assert(phase->start() == start, "Incorrect start");
sla@5237:     assert(phase->end() == end, "Incorrect end");
sla@5237:   }
sla@5237: 
sla@5237:   static void one_pause() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase", 2);
sla@5237:     time_partitions.report_gc_phase_end(8);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 8);
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(8) - Ticks(2), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(8) - Ticks(2), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: 
sla@5237:   static void two_pauses() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase1", 2);
sla@5237:     time_partitions.report_gc_phase_end(3);
sla@5237:     time_partitions.report_gc_phase_start("PausePhase2", 4);
sla@5237:     time_partitions.report_gc_phase_end(6);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase1", 2, 3);
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase2", 4, 6);
sla@5237: 
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(2) - Ticks(0), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: 
sla@5237:   static void one_sub_pause_phase() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase", 2);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase", 3);
sla@5237:     time_partitions.report_gc_phase_end(4);
sla@5237:     time_partitions.report_gc_phase_end(5);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 5);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase", 3, 4);
sla@5237: 
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(3) - Ticks(0), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: 
sla@5237:   static void max_nested_pause_phases() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase", 2);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase1", 3);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase2", 4);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase3", 5);
sla@5237:     time_partitions.report_gc_phase_end(6);
sla@5237:     time_partitions.report_gc_phase_end(7);
sla@5237:     time_partitions.report_gc_phase_end(8);
sla@5237:     time_partitions.report_gc_phase_end(9);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 9);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
sla@5237:     validate_pause_phase(iter.next(), 2, "SubPhase2", 4, 7);
sla@5237:     validate_pause_phase(iter.next(), 3, "SubPhase3", 5, 6);
sla@5237: 
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(7) - Ticks(0), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(7) - Ticks(0), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: 
sla@5237:   static void many_sub_pause_phases() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase", 2);
sla@5237: 
sla@5237:     time_partitions.report_gc_phase_start("SubPhase1", 3);
sla@5237:     time_partitions.report_gc_phase_end(4);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase2", 5);
sla@5237:     time_partitions.report_gc_phase_end(6);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase3", 7);
sla@5237:     time_partitions.report_gc_phase_end(8);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase4", 9);
sla@5237:     time_partitions.report_gc_phase_end(10);
sla@5237: 
sla@5237:     time_partitions.report_gc_phase_end(11);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 11);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 4);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase2", 5, 6);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase3", 7, 8);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase4", 9, 10);
sla@5237: 
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(9) - Ticks(0), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(9) - Ticks(0), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: 
sla@5237:   static void many_sub_pause_phases2() {
sla@5237:     TimePartitions time_partitions;
sla@5237:     time_partitions.report_gc_phase_start("PausePhase", 2);
sla@5237: 
sla@5237:     time_partitions.report_gc_phase_start("SubPhase1", 3);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase11", 4);
sla@5237:     time_partitions.report_gc_phase_end(5);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase12", 6);
sla@5237:     time_partitions.report_gc_phase_end(7);
sla@5237:     time_partitions.report_gc_phase_end(8);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase2", 9);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase21", 10);
sla@5237:     time_partitions.report_gc_phase_end(11);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase22", 12);
sla@5237:     time_partitions.report_gc_phase_end(13);
sla@5237:     time_partitions.report_gc_phase_end(14);
sla@5237:     time_partitions.report_gc_phase_start("SubPhase3", 15);
sla@5237:     time_partitions.report_gc_phase_end(16);
sla@5237: 
sla@5237:     time_partitions.report_gc_phase_end(17);
sla@5237: 
sla@5237:     TimePartitionPhasesIterator iter(&time_partitions);
sla@5237: 
sla@5237:     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 17);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
sla@5237:     validate_pause_phase(iter.next(), 2, "SubPhase11", 4, 5);
sla@5237:     validate_pause_phase(iter.next(), 2, "SubPhase12", 6, 7);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase2", 9, 14);
sla@5237:     validate_pause_phase(iter.next(), 2, "SubPhase21", 10, 11);
sla@5237:     validate_pause_phase(iter.next(), 2, "SubPhase22", 12, 13);
sla@5237:     validate_pause_phase(iter.next(), 1, "SubPhase3", 15, 16);
sla@5237: 
mgronlun@6131:     assert(time_partitions.sum_of_pauses() == Ticks(15) - Ticks(0), "Incorrect");
mgronlun@6131:     assert(time_partitions.longest_pause() == Ticks(15) - Ticks(0), "Incorrect");
sla@5237: 
sla@5237:     assert(!iter.has_next(), "Too many elements");
sla@5237:   }
sla@5237: };
sla@5237: 
sla@5237: class GCTimerTest {
sla@5237: public:
sla@5237:   static void all() {
sla@5237:     gc_start();
sla@5237:     gc_end();
sla@5237:   }
sla@5237: 
sla@5237:   static void gc_start() {
sla@5237:     GCTimer gc_timer;
sla@5237:     gc_timer.register_gc_start(1);
sla@5237: 
sla@5237:     assert(gc_timer.gc_start() == 1, "Incorrect");
sla@5237:   }
sla@5237: 
sla@5237:   static void gc_end() {
sla@5237:     GCTimer gc_timer;
sla@5237:     gc_timer.register_gc_start(1);
sla@5237:     gc_timer.register_gc_end(2);
sla@5237: 
sla@5237:     assert(gc_timer.gc_end() == 2, "Incorrect");
sla@5237:   }
sla@5237: };
sla@5237: 
sla@5237: void GCTimerAllTest::all() {
sla@5237:   GCTimerTest::all();
sla@5237:   TimePartitionPhasesIteratorTest::all();
sla@5237: }
sla@5237: 
sla@5237: #endif