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   GCTimer::register_gc_pause_start(name);
  73 }
  74 
  75 void ConcurrentGCTimer::register_gc_pause_end() {
  76   GCTimer::register_gc_pause_end();
  77 }
  78 
  79 void PhasesStack::clear() {
  80   _next_phase_level = 0;
  81 }
  82 
  83 void PhasesStack::push(int phase_index) {
  84   assert(_next_phase_level < PHASE_LEVELS, "Overflow");
  85 
  86   _phase_indices[_next_phase_level] = phase_index;
  87 
  88   _next_phase_level++;
  89 }
  90 
  91 int PhasesStack::pop() {
  92   assert(_next_phase_level > 0, "Underflow");
  93 
  94   _next_phase_level--;
  95 
  96   return _phase_indices[_next_phase_level];
  97 }
  98 
  99 int PhasesStack::count() const {
 100   return _next_phase_level;
 101 }
 102 
 103 
 104 TimePartitions::TimePartitions() {
 105   _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<PausePhase>(INITIAL_CAPACITY, true, mtGC);
 106   clear();
 107 }
 108 
 109 TimePartitions::~TimePartitions() {
 110   delete _phases;
 111   _phases = NULL;
 112 }
 113 
 114 void TimePartitions::clear() {
 115   _phases->clear();
 116   _active_phases.clear();
 117   _sum_of_pauses = Tickspan();
 118   _longest_pause = Tickspan();
 119 }
 120 
 121 void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time) {
 122   assert(_phases->length() <= 1000, "Too many recored phases?");
 123 
 124   int level = _active_phases.count();
 125 
 126   PausePhase phase;
 127   phase.set_level(level);
 128   phase.set_name(name);
 129   phase.set_start(time);
 130 
 131   int index = _phases->append(phase);
 132 
 133   _active_phases.push(index);
 134 }
 135 
 136 void TimePartitions::update_statistics(GCPhase* phase) {
 137   // FIXME: This should only be done for pause phases
 138   if (phase->level() == 0) {
 139     const Tickspan pause = phase->end() - phase->start();
 140     _sum_of_pauses += pause;
 141     _longest_pause = MAX2(pause, _longest_pause);
 142   }
 143 }
 144 
 145 void TimePartitions::report_gc_phase_end(const Ticks& time) {
 146   int phase_index = _active_phases.pop();
 147   GCPhase* phase = _phases->adr_at(phase_index);
 148   phase->set_end(time);
 149   update_statistics(phase);
 150 }
 151 
 152 int TimePartitions::num_phases() const {
 153   return _phases->length();
 154 }
 155 
 156 GCPhase* TimePartitions::phase_at(int index) const {
 157   assert(index >= 0, "Out of bounds");
 158   assert(index < _phases->length(), "Out of bounds");
 159 
 160   return _phases->adr_at(index);
 161 }
 162 
 163 bool TimePartitions::has_active_phases() {
 164   return _active_phases.count() > 0;
 165 }
 166 
 167 bool TimePartitionPhasesIterator::has_next() {
 168   return _next < _time_partitions->num_phases();
 169 }
 170 
 171 GCPhase* TimePartitionPhasesIterator::next() {
 172   assert(has_next(), "Must have phases left");
 173   return _time_partitions->phase_at(_next++);
 174 }
 175 
 176 
 177 /////////////// Unit tests ///////////////
 178 
 179 #ifndef PRODUCT
 180 
 181 class TimePartitionPhasesIteratorTest {
 182  public:
 183   static void all() {
 184     one_pause();
 185     two_pauses();
 186     one_sub_pause_phase();
 187     many_sub_pause_phases();
 188     many_sub_pause_phases2();
 189     max_nested_pause_phases();
 190   }
 191 
 192   static void validate_pause_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {
 193     assert(phase->level() == level, "Incorrect level");
 194     assert(strcmp(phase->name(), name) == 0, "Incorrect name");
 195     assert(phase->start() == start, "Incorrect start");
 196     assert(phase->end() == end, "Incorrect end");
 197   }
 198 
 199   static void one_pause() {
 200     TimePartitions time_partitions;
 201     time_partitions.report_gc_phase_start("PausePhase", 2);
 202     time_partitions.report_gc_phase_end(8);
 203 
 204     TimePartitionPhasesIterator iter(&time_partitions);
 205 
 206     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 8);
 207     assert(time_partitions.sum_of_pauses() == Ticks(8) - Ticks(2), "Incorrect");
 208     assert(time_partitions.longest_pause() == Ticks(8) - Ticks(2), "Incorrect");
 209 
 210     assert(!iter.has_next(), "Too many elements");
 211   }
 212 
 213   static void two_pauses() {
 214     TimePartitions time_partitions;
 215     time_partitions.report_gc_phase_start("PausePhase1", 2);
 216     time_partitions.report_gc_phase_end(3);
 217     time_partitions.report_gc_phase_start("PausePhase2", 4);
 218     time_partitions.report_gc_phase_end(6);
 219 
 220     TimePartitionPhasesIterator iter(&time_partitions);
 221 
 222     validate_pause_phase(iter.next(), 0, "PausePhase1", 2, 3);
 223     validate_pause_phase(iter.next(), 0, "PausePhase2", 4, 6);
 224 
 225     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
 226     assert(time_partitions.longest_pause() == Ticks(2) - Ticks(0), "Incorrect");
 227 
 228     assert(!iter.has_next(), "Too many elements");
 229   }
 230 
 231   static void one_sub_pause_phase() {
 232     TimePartitions time_partitions;
 233     time_partitions.report_gc_phase_start("PausePhase", 2);
 234     time_partitions.report_gc_phase_start("SubPhase", 3);
 235     time_partitions.report_gc_phase_end(4);
 236     time_partitions.report_gc_phase_end(5);
 237 
 238     TimePartitionPhasesIterator iter(&time_partitions);
 239 
 240     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 5);
 241     validate_pause_phase(iter.next(), 1, "SubPhase", 3, 4);
 242 
 243     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
 244     assert(time_partitions.longest_pause() == Ticks(3) - Ticks(0), "Incorrect");
 245 
 246     assert(!iter.has_next(), "Too many elements");
 247   }
 248 
 249   static void max_nested_pause_phases() {
 250     TimePartitions time_partitions;
 251     time_partitions.report_gc_phase_start("PausePhase", 2);
 252     time_partitions.report_gc_phase_start("SubPhase1", 3);
 253     time_partitions.report_gc_phase_start("SubPhase2", 4);
 254     time_partitions.report_gc_phase_start("SubPhase3", 5);
 255     time_partitions.report_gc_phase_end(6);
 256     time_partitions.report_gc_phase_end(7);
 257     time_partitions.report_gc_phase_end(8);
 258     time_partitions.report_gc_phase_end(9);
 259 
 260     TimePartitionPhasesIterator iter(&time_partitions);
 261 
 262     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 9);
 263     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
 264     validate_pause_phase(iter.next(), 2, "SubPhase2", 4, 7);
 265     validate_pause_phase(iter.next(), 3, "SubPhase3", 5, 6);
 266 
 267     assert(time_partitions.sum_of_pauses() == Ticks(7) - Ticks(0), "Incorrect");
 268     assert(time_partitions.longest_pause() == Ticks(7) - Ticks(0), "Incorrect");
 269 
 270     assert(!iter.has_next(), "Too many elements");
 271   }
 272 
 273   static void many_sub_pause_phases() {
 274     TimePartitions time_partitions;
 275     time_partitions.report_gc_phase_start("PausePhase", 2);
 276 
 277     time_partitions.report_gc_phase_start("SubPhase1", 3);
 278     time_partitions.report_gc_phase_end(4);
 279     time_partitions.report_gc_phase_start("SubPhase2", 5);
 280     time_partitions.report_gc_phase_end(6);
 281     time_partitions.report_gc_phase_start("SubPhase3", 7);
 282     time_partitions.report_gc_phase_end(8);
 283     time_partitions.report_gc_phase_start("SubPhase4", 9);
 284     time_partitions.report_gc_phase_end(10);
 285 
 286     time_partitions.report_gc_phase_end(11);
 287 
 288     TimePartitionPhasesIterator iter(&time_partitions);
 289 
 290     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 11);
 291     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 4);
 292     validate_pause_phase(iter.next(), 1, "SubPhase2", 5, 6);
 293     validate_pause_phase(iter.next(), 1, "SubPhase3", 7, 8);
 294     validate_pause_phase(iter.next(), 1, "SubPhase4", 9, 10);
 295 
 296     assert(time_partitions.sum_of_pauses() == Ticks(9) - Ticks(0), "Incorrect");
 297     assert(time_partitions.longest_pause() == Ticks(9) - Ticks(0), "Incorrect");
 298 
 299     assert(!iter.has_next(), "Too many elements");
 300   }
 301 
 302   static void many_sub_pause_phases2() {
 303     TimePartitions time_partitions;
 304     time_partitions.report_gc_phase_start("PausePhase", 2);
 305 
 306     time_partitions.report_gc_phase_start("SubPhase1", 3);
 307     time_partitions.report_gc_phase_start("SubPhase11", 4);
 308     time_partitions.report_gc_phase_end(5);
 309     time_partitions.report_gc_phase_start("SubPhase12", 6);
 310     time_partitions.report_gc_phase_end(7);
 311     time_partitions.report_gc_phase_end(8);
 312     time_partitions.report_gc_phase_start("SubPhase2", 9);
 313     time_partitions.report_gc_phase_start("SubPhase21", 10);
 314     time_partitions.report_gc_phase_end(11);
 315     time_partitions.report_gc_phase_start("SubPhase22", 12);
 316     time_partitions.report_gc_phase_end(13);
 317     time_partitions.report_gc_phase_end(14);
 318     time_partitions.report_gc_phase_start("SubPhase3", 15);
 319     time_partitions.report_gc_phase_end(16);
 320 
 321     time_partitions.report_gc_phase_end(17);
 322 
 323     TimePartitionPhasesIterator iter(&time_partitions);
 324 
 325     validate_pause_phase(iter.next(), 0, "PausePhase", 2, 17);
 326     validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
 327     validate_pause_phase(iter.next(), 2, "SubPhase11", 4, 5);
 328     validate_pause_phase(iter.next(), 2, "SubPhase12", 6, 7);
 329     validate_pause_phase(iter.next(), 1, "SubPhase2", 9, 14);
 330     validate_pause_phase(iter.next(), 2, "SubPhase21", 10, 11);
 331     validate_pause_phase(iter.next(), 2, "SubPhase22", 12, 13);
 332     validate_pause_phase(iter.next(), 1, "SubPhase3", 15, 16);
 333 
 334     assert(time_partitions.sum_of_pauses() == Ticks(15) - Ticks(0), "Incorrect");
 335     assert(time_partitions.longest_pause() == Ticks(15) - Ticks(0), "Incorrect");
 336 
 337     assert(!iter.has_next(), "Too many elements");
 338   }
 339 };
 340 
 341 class GCTimerTest {
 342 public:
 343   static void all() {
 344     gc_start();
 345     gc_end();
 346   }
 347 
 348   static void gc_start() {
 349     GCTimer gc_timer;
 350     gc_timer.register_gc_start(1);
 351 
 352     assert(gc_timer.gc_start() == 1, "Incorrect");
 353   }
 354 
 355   static void gc_end() {
 356     GCTimer gc_timer;
 357     gc_timer.register_gc_start(1);
 358     gc_timer.register_gc_end(2);
 359 
 360     assert(gc_timer.gc_end() == 2, "Incorrect");
 361   }
 362 };
 363 
 364 void GCTimerAllTest::all() {
 365   GCTimerTest::all();
 366   TimePartitionPhasesIteratorTest::all();
 367 }
 368 
 369 #endif