1 /*
   2  * Copyright (c) 2012, 2018, 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, const Ticks& time) {
  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, time);
  74 }
  75 
  76 void ConcurrentGCTimer::register_gc_pause_end(const Ticks& time) {
  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(time);
  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
--- EOF ---