1 /*

     2  * Copyright (c) 2012, 2015, Oracle and/or its affiliates. All rights reserved.

     3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.

     4  *

     5  * This code is free software; you can redistribute it and/or modify it

     6  * under the terms of the GNU General Public License version 2 only, as

     7  * published by the Free Software Foundation.

     8  *

     9  * This code is distributed in the hope that it will be useful, but WITHOUT

    10  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or

    11  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License

    12  * version 2 for more details (a copy is included in the LICENSE file that

    13  * accompanied this code).

    14  *

    15  * You should have received a copy of the GNU General Public License version

    16  * 2 along with this work; if not, write to the Free Software Foundation,

    17  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.

    18  *

    19  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA

    20  * or visit www.oracle.com if you need additional information or have any

    21  * questions.

    22  *

    23  */

    24 

    25 #include "precompiled.hpp"

    26 #include "gc/shared/gcTimer.hpp"

    27 #include "utilities/growableArray.hpp"

    28 #include "utilities/ticks.inline.hpp"

    29 

    30 // the "time" parameter for most functions

    31 // has a default value set by Ticks::now()

    32 

    33 void GCTimer::register_gc_start(const Ticks& time) {

    34   _time_partitions.clear();

    35   _gc_start = time;

    36 }

    37 

    38 void GCTimer::register_gc_end(const Ticks& time) {

    39   assert(!_time_partitions.has_active_phases(),

    40       "We should have ended all started phases, before ending the GC");

    41 

    42   _gc_end = time;

    43 }

    44 

    45 void GCTimer::register_gc_pause_start(const char* name, const Ticks& time) {

    46   _time_partitions.report_gc_phase_start(name, time);

    47 }

    48 

    49 void GCTimer::register_gc_pause_end(const Ticks& time) {

    50   _time_partitions.report_gc_phase_end(time);

    51 }

    52 

    53 void GCTimer::register_gc_phase_start(const char* name, const Ticks& time) {

    54   _time_partitions.report_gc_phase_start(name, time);

    55 }

    56 

    57 void GCTimer::register_gc_phase_end(const Ticks& time) {

    58   _time_partitions.report_gc_phase_end(time);

    59 }

    60 

    61 void STWGCTimer::register_gc_start(const Ticks& time) {

    62   GCTimer::register_gc_start(time);

    63   register_gc_pause_start("GC Pause", time);

    64 }

    65 

    66 void STWGCTimer::register_gc_end(const Ticks& time) {

    67   register_gc_pause_end(time);

    68   GCTimer::register_gc_end(time);

    69 }

    70 

    71 void ConcurrentGCTimer::register_gc_pause_start(const char* name) {

    72   assert(!_is_concurrent_phase_active, "A pause phase can't be started while a concurrent phase is active.");

    73   GCTimer::register_gc_pause_start(name);

    74 }

    75 

    76 void ConcurrentGCTimer::register_gc_pause_end() {

    77   assert(!_is_concurrent_phase_active, "A pause phase can't be ended while a concurrent phase is active.");

    78   GCTimer::register_gc_pause_end();

    79 }

    80 

    81 void ConcurrentGCTimer::register_gc_concurrent_start(const char* name, const Ticks& time) {

    82   assert(!_is_concurrent_phase_active, "A concurrent phase is already active.");

    83   _time_partitions.report_gc_phase_start(name, time, GCPhase::ConcurrentPhaseType);

    84   _is_concurrent_phase_active = true;

    85 }

    86 

    87 void ConcurrentGCTimer::register_gc_concurrent_end(const Ticks& time) {

    88   assert(_is_concurrent_phase_active, "A concurrent phase is not active.");

    89   _time_partitions.report_gc_phase_end(time, GCPhase::ConcurrentPhaseType);

    90   _is_concurrent_phase_active = false;

    91 }

    92 

    93 void PhasesStack::clear() {

    94   _next_phase_level = 0;

    95 }

    96 

    97 void PhasesStack::push(int phase_index) {

    98   assert(_next_phase_level < PHASE_LEVELS, "Overflow");

    99 

   100   _phase_indices[_next_phase_level] = phase_index;

   101   _next_phase_level++;

   102 }

   103 

   104 int PhasesStack::pop() {

   105   assert(_next_phase_level > 0, "Underflow");

   106 

   107   _next_phase_level--;

   108   return _phase_indices[_next_phase_level];

   109 }

   110 

   111 int PhasesStack::count() const {

   112   return _next_phase_level;

   113 }

   114 

   115 TimePartitions::TimePartitions() {

   116   _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<GCPhase>(INITIAL_CAPACITY, true, mtGC);

   117   clear();

   118 }

   119 

   120 TimePartitions::~TimePartitions() {

   121   delete _phases;

   122   _phases = NULL;

   123 }

   124 

   125 void TimePartitions::clear() {

   126   _phases->clear();

   127   _active_phases.clear();

   128   _sum_of_pauses = Tickspan();

   129   _longest_pause = Tickspan();

   130 }

   131 

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

   133   assert(_phases->length() <= 1000, "Too many recored phases?");

   134 

   135   int level = _active_phases.count();

   136 

   137   GCPhase phase;

   138   phase.set_type(type);

   139   phase.set_level(level);

   140   phase.set_name(name);

   141   phase.set_start(time);

   142 

   143   int index = _phases->append(phase);

   144 

   145   _active_phases.push(index);

   146 }

   147 

   148 void TimePartitions::update_statistics(GCPhase* phase) {

   149   if ((phase->type() == GCPhase::PausePhaseType) && (phase->level() == 0)) {

   150     const Tickspan pause = phase->end() - phase->start();

   151     _sum_of_pauses += pause;

   152     _longest_pause = MAX2(pause, _longest_pause);

   153   }

   154 }

   155 

   156 void TimePartitions::report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type) {

   157   int phase_index = _active_phases.pop();

   158   GCPhase* phase = _phases->adr_at(phase_index);

   159   phase->set_end(time);

   160   update_statistics(phase);

   161 }

   162 

   163 int TimePartitions::num_phases() const {

   164   return _phases->length();

   165 }

   166 

   167 GCPhase* TimePartitions::phase_at(int index) const {

   168   assert(index >= 0, "Out of bounds");

   169   assert(index < _phases->length(), "Out of bounds");

   170 

   171   return _phases->adr_at(index);

   172 }

   173 

   174 bool TimePartitions::has_active_phases() {

   175   return _active_phases.count() > 0;

   176 }

   177 

   178 bool TimePartitionPhasesIterator::has_next() {

   179   return _next < _time_partitions->num_phases();

   180 }

   181 

   182 GCPhase* TimePartitionPhasesIterator::next() {

   183   assert(has_next(), "Must have phases left");

   184   return _time_partitions->phase_at(_next++);

   185 }

   186 

   187 

   188 /////////////// Unit tests ///////////////

   189 

   190 #ifndef PRODUCT

   191 

   192 class TimePartitionPhasesIteratorTest {

   193  public:

   194   static void all() {

   195     one_pause();

   196     two_pauses();

   197     one_sub_pause_phase();

   198     many_sub_pause_phases();

   199     many_sub_pause_phases2();

   200     max_nested_pause_phases();

   201     one_concurrent();

   202   }

   203 

   204   static void validate_gc_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {

   205     assert(phase->level() == level, "Incorrect level");

   206     assert(strcmp(phase->name(), name) == 0, "Incorrect name");

   207     assert(phase->start() == start, "Incorrect start");

   208     assert(phase->end() == end, "Incorrect end");

   209   }

   210 

   211   static void one_pause() {

   212     TimePartitions time_partitions;

   213     time_partitions.report_gc_phase_start("PausePhase", 2);

   214     time_partitions.report_gc_phase_end(8);

   215 

   216     TimePartitionPhasesIterator iter(&time_partitions);

   217 

   218     validate_gc_phase(iter.next(), 0, "PausePhase", 2, 8);

   219     assert(time_partitions.sum_of_pauses() == Ticks(8) - Ticks(2), "Incorrect");

   220     assert(time_partitions.longest_pause() == Ticks(8) - Ticks(2), "Incorrect");

   221 

   222     assert(!iter.has_next(), "Too many elements");

   223   }

   224 

   225   static void two_pauses() {

   226     TimePartitions time_partitions;

   227     time_partitions.report_gc_phase_start("PausePhase1", 2);

   228     time_partitions.report_gc_phase_end(3);

   229     time_partitions.report_gc_phase_start("PausePhase2", 4);

   230     time_partitions.report_gc_phase_end(6);

   231 

   232     TimePartitionPhasesIterator iter(&time_partitions);

   233 

   234     validate_gc_phase(iter.next(), 0, "PausePhase1", 2, 3);

   235     validate_gc_phase(iter.next(), 0, "PausePhase2", 4, 6);

   236 

   237     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");

   238     assert(time_partitions.longest_pause() == Ticks(2) - Ticks(0), "Incorrect");

   239 

   240     assert(!iter.has_next(), "Too many elements");

   241   }

   242 

   243   static void one_sub_pause_phase() {

   244     TimePartitions time_partitions;

   245     time_partitions.report_gc_phase_start("PausePhase", 2);

   246     time_partitions.report_gc_phase_start("SubPhase", 3);

   247     time_partitions.report_gc_phase_end(4);

   248     time_partitions.report_gc_phase_end(5);

   249 

   250     TimePartitionPhasesIterator iter(&time_partitions);

   251 

   252     validate_gc_phase(iter.next(), 0, "PausePhase", 2, 5);

   253     validate_gc_phase(iter.next(), 1, "SubPhase", 3, 4);

   254 

   255     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");

   256     assert(time_partitions.longest_pause() == Ticks(3) - Ticks(0), "Incorrect");

   257 

   258     assert(!iter.has_next(), "Too many elements");

   259   }

   260 

   261   static void max_nested_pause_phases() {

   262     TimePartitions time_partitions;

   263     time_partitions.report_gc_phase_start("PausePhase", 2);

   264     time_partitions.report_gc_phase_start("SubPhase1", 3);

   265     time_partitions.report_gc_phase_start("SubPhase2", 4);

   266     time_partitions.report_gc_phase_start("SubPhase3", 5);

   267     time_partitions.report_gc_phase_end(6);

   268     time_partitions.report_gc_phase_end(7);

   269     time_partitions.report_gc_phase_end(8);

   270     time_partitions.report_gc_phase_end(9);

   271 

   272     TimePartitionPhasesIterator iter(&time_partitions);

   273 

   274     validate_gc_phase(iter.next(), 0, "PausePhase", 2, 9);

   275     validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);

   276     validate_gc_phase(iter.next(), 2, "SubPhase2", 4, 7);

   277     validate_gc_phase(iter.next(), 3, "SubPhase3", 5, 6);

   278 

   279     assert(time_partitions.sum_of_pauses() == Ticks(7) - Ticks(0), "Incorrect");

   280     assert(time_partitions.longest_pause() == Ticks(7) - Ticks(0), "Incorrect");

   281 

   282     assert(!iter.has_next(), "Too many elements");

   283   }

   284 

   285   static void many_sub_pause_phases() {

   286     TimePartitions time_partitions;

   287     time_partitions.report_gc_phase_start("PausePhase", 2);

   288 

   289     time_partitions.report_gc_phase_start("SubPhase1", 3);

   290     time_partitions.report_gc_phase_end(4);

   291     time_partitions.report_gc_phase_start("SubPhase2", 5);

   292     time_partitions.report_gc_phase_end(6);

   293     time_partitions.report_gc_phase_start("SubPhase3", 7);

   294     time_partitions.report_gc_phase_end(8);

   295     time_partitions.report_gc_phase_start("SubPhase4", 9);

   296     time_partitions.report_gc_phase_end(10);

   297 

   298     time_partitions.report_gc_phase_end(11);

   299 

   300     TimePartitionPhasesIterator iter(&time_partitions);

   301 

   302     validate_gc_phase(iter.next(), 0, "PausePhase", 2, 11);

   303     validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 4);

   304     validate_gc_phase(iter.next(), 1, "SubPhase2", 5, 6);

   305     validate_gc_phase(iter.next(), 1, "SubPhase3", 7, 8);

   306     validate_gc_phase(iter.next(), 1, "SubPhase4", 9, 10);

   307 

   308     assert(time_partitions.sum_of_pauses() == Ticks(9) - Ticks(0), "Incorrect");

   309     assert(time_partitions.longest_pause() == Ticks(9) - Ticks(0), "Incorrect");

   310 

   311     assert(!iter.has_next(), "Too many elements");

   312   }

   313 

   314   static void many_sub_pause_phases2() {

   315     TimePartitions time_partitions;

   316     time_partitions.report_gc_phase_start("PausePhase", 2);

   317 

   318     time_partitions.report_gc_phase_start("SubPhase1", 3);

   319     time_partitions.report_gc_phase_start("SubPhase11", 4);

   320     time_partitions.report_gc_phase_end(5);

   321     time_partitions.report_gc_phase_start("SubPhase12", 6);

   322     time_partitions.report_gc_phase_end(7);

   323     time_partitions.report_gc_phase_end(8);

   324     time_partitions.report_gc_phase_start("SubPhase2", 9);

   325     time_partitions.report_gc_phase_start("SubPhase21", 10);

   326     time_partitions.report_gc_phase_end(11);

   327     time_partitions.report_gc_phase_start("SubPhase22", 12);

   328     time_partitions.report_gc_phase_end(13);

   329     time_partitions.report_gc_phase_end(14);

   330     time_partitions.report_gc_phase_start("SubPhase3", 15);

   331     time_partitions.report_gc_phase_end(16);

   332 

   333     time_partitions.report_gc_phase_end(17);

   334 

   335     TimePartitionPhasesIterator iter(&time_partitions);

   336 

   337     validate_gc_phase(iter.next(), 0, "PausePhase", 2, 17);

   338     validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);

   339     validate_gc_phase(iter.next(), 2, "SubPhase11", 4, 5);

   340     validate_gc_phase(iter.next(), 2, "SubPhase12", 6, 7);

   341     validate_gc_phase(iter.next(), 1, "SubPhase2", 9, 14);

   342     validate_gc_phase(iter.next(), 2, "SubPhase21", 10, 11);

   343     validate_gc_phase(iter.next(), 2, "SubPhase22", 12, 13);

   344     validate_gc_phase(iter.next(), 1, "SubPhase3", 15, 16);

   345 

   346     assert(time_partitions.sum_of_pauses() == Ticks(15) - Ticks(0), "Incorrect");

   347     assert(time_partitions.longest_pause() == Ticks(15) - Ticks(0), "Incorrect");

   348 

   349     assert(!iter.has_next(), "Too many elements");

   350   }

   351 

   352   static void one_concurrent() {

   353     TimePartitions time_partitions;

   354     time_partitions.report_gc_phase_start("ConcurrentPhase", 2, GCPhase::ConcurrentPhaseType);

   355     time_partitions.report_gc_phase_end(8, GCPhase::ConcurrentPhaseType);

   356 

   357     TimePartitionPhasesIterator iter(&time_partitions);

   358 

   359     validate_gc_phase(iter.next(), 0, "ConcurrentPhase", 2, 8);

   360     // ConcurrentPhaseType should not affect to both 'sum_of_pauses()' and 'longest_pause()'.

   361     assert(time_partitions.sum_of_pauses() == Tickspan(), "Incorrect");

   362     assert(time_partitions.longest_pause() == Tickspan(), "Incorrect");

   363 

   364     assert(!iter.has_next(), "Too many elements");

   365   }

   366 };

   367 

   368 class GCTimerTest {

   369 public:

   370   static void all() {

   371     gc_start();

   372     gc_end();

   373   }

   374 

   375   static void gc_start() {

   376     GCTimer gc_timer;

   377     gc_timer.register_gc_start(1);

   378 

   379     assert(gc_timer.gc_start() == 1, "Incorrect");

   380   }

   381 

   382   static void gc_end() {

   383     GCTimer gc_timer;

   384     gc_timer.register_gc_start(1);

   385     gc_timer.register_gc_end(2);

   386 

   387     assert(gc_timer.gc_end() == 2, "Incorrect");

   388   }

   389 };

   390 

   391 void GCTimer_test() {

   392   GCTimerTest::all();

   393   TimePartitionPhasesIteratorTest::all();

   394 }

   395 

   396 #endif