src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

Print this page
rev 4561 : 7176479: G1: JVM crashes on T5-8 system with 1.5 TB heap
Summary: Refactor G1's hot card cache and card counts table into their own files. Simplify the card counts table, including removing the encoding of the card index in each entry. The card counts table now has a 1:1 correspondence with the cards spanned by heap. Space for the card counts table is reserved from virtual memory (rather than C heap) during JVM startup and is committed/expanded when the heap is expanded. Changes were also reviewed-by Vitaly Davidovich.
Reviewed-by:
   1 /*
   2  * Copyright (c) 2012, 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  *


 138 template <class T>
 139 void WorkerDataArray<T>::reset() {
 140   for (uint i = 0; i < _length; i++) {
 141     _data[i] = (T)_uninitialized;
 142   }
 143 }
 144 
 145 template <class T>
 146 void WorkerDataArray<T>::verify() {
 147   for (uint i = 0; i < _length; i++) {
 148     assert(_data[i] != _uninitialized,
 149         err_msg("Invalid data for worker " UINT32_FORMAT ", data: %lf, uninitialized: %lf",
 150             i, (double)_data[i], (double)_uninitialized));
 151   }
 152 }
 153 
 154 #endif
 155 
 156 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
 157   _max_gc_threads(max_gc_threads),
 158   _min_clear_cc_time_ms(-1.0),
 159   _max_clear_cc_time_ms(-1.0),
 160   _cur_clear_cc_time_ms(0.0),
 161   _cum_clear_cc_time_ms(0.0),
 162   _num_cc_clears(0L),
 163   _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
 164   _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
 165   _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
 166   _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
 167   _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
 168   _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
 169   _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
 170   _last_termination_times_ms(_max_gc_threads, "%.1lf"),
 171   _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
 172   _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
 173   _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
 174   _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf")
 175 {
 176   assert(max_gc_threads > 0, "Must have some GC threads");
 177 }
 178 
 179 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
 180   assert(active_gc_threads > 0, "The number of threads must be > 0");
 181   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
 182   _active_gc_threads = active_gc_threads;


 268     _last_obj_copy_times_ms.print(2, "Object Copy (ms)");
 269     _last_termination_times_ms.print(2, "Termination (ms)");
 270     if (G1Log::finest()) {
 271       _last_termination_attempts.print(3, "Termination Attempts");
 272     }
 273     _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
 274     _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
 275     _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
 276   } else {
 277     _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)");
 278     if (_last_satb_filtering_times_ms.sum() > 0.0) {
 279       _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)");
 280     }
 281     _last_update_rs_times_ms.print(1, "Update RS (ms)");
 282       _last_update_rs_processed_buffers.print(2, "Processed Buffers");
 283     _last_scan_rs_times_ms.print(1, "Scan RS (ms)");
 284     _last_obj_copy_times_ms.print(1, "Object Copy (ms)");
 285   }
 286   print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 287   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 288   if (Verbose && G1Log::finest()) {
 289     print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
 290     print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
 291     print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
 292     print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
 293     if (_num_cc_clears > 0) {
 294       print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
 295     }
 296   }
 297   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 298   print_stats(1, "Other", misc_time_ms);
 299   if (_cur_verify_before_time_ms > 0.0) {
 300     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
 301   }
 302   print_stats(2, "Choose CSet",
 303     (_recorded_young_cset_choice_time_ms +
 304     _recorded_non_young_cset_choice_time_ms));
 305   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
 306   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
 307   print_stats(2, "Free CSet",
 308     (_recorded_young_free_cset_time_ms +
 309     _recorded_non_young_free_cset_time_ms));
 310   if (_cur_verify_after_time_ms > 0.0) {
 311     print_stats(2, "Verify After", _cur_verify_after_time_ms);
 312   }
 313 }
 314 
 315 void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) {
 316   if (!(Verbose && G1Log::finest())) {
 317     return;
 318   }
 319 
 320   if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms) {
 321     _min_clear_cc_time_ms = ms;
 322   }
 323   if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms) {
 324     _max_clear_cc_time_ms = ms;
 325   }
 326   _cur_clear_cc_time_ms = ms;
 327   _cum_clear_cc_time_ms += ms;
 328   _num_cc_clears++;
 329 }
   1 /*
   2  * Copyright (c) 2013, 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  *


 138 template <class T>
 139 void WorkerDataArray<T>::reset() {
 140   for (uint i = 0; i < _length; i++) {
 141     _data[i] = (T)_uninitialized;
 142   }
 143 }
 144 
 145 template <class T>
 146 void WorkerDataArray<T>::verify() {
 147   for (uint i = 0; i < _length; i++) {
 148     assert(_data[i] != _uninitialized,
 149         err_msg("Invalid data for worker " UINT32_FORMAT ", data: %lf, uninitialized: %lf",
 150             i, (double)_data[i], (double)_uninitialized));
 151   }
 152 }
 153 
 154 #endif
 155 
 156 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
 157   _max_gc_threads(max_gc_threads),





 158   _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
 159   _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
 160   _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
 161   _last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
 162   _last_update_rs_processed_buffers(_max_gc_threads, "%d"),
 163   _last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
 164   _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
 165   _last_termination_times_ms(_max_gc_threads, "%.1lf"),
 166   _last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
 167   _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
 168   _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
 169   _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf")
 170 {
 171   assert(max_gc_threads > 0, "Must have some GC threads");
 172 }
 173 
 174 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
 175   assert(active_gc_threads > 0, "The number of threads must be > 0");
 176   assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
 177   _active_gc_threads = active_gc_threads;


 263     _last_obj_copy_times_ms.print(2, "Object Copy (ms)");
 264     _last_termination_times_ms.print(2, "Termination (ms)");
 265     if (G1Log::finest()) {
 266       _last_termination_attempts.print(3, "Termination Attempts");
 267     }
 268     _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
 269     _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
 270     _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
 271   } else {
 272     _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)");
 273     if (_last_satb_filtering_times_ms.sum() > 0.0) {
 274       _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)");
 275     }
 276     _last_update_rs_times_ms.print(1, "Update RS (ms)");
 277       _last_update_rs_processed_buffers.print(2, "Processed Buffers");
 278     _last_scan_rs_times_ms.print(1, "Scan RS (ms)");
 279     _last_obj_copy_times_ms.print(1, "Object Copy (ms)");
 280   }
 281   print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
 282   print_stats(1, "Clear CT", _cur_clear_ct_time_ms);









 283   double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
 284   print_stats(1, "Other", misc_time_ms);
 285   if (_cur_verify_before_time_ms > 0.0) {
 286     print_stats(2, "Verify Before", _cur_verify_before_time_ms);
 287   }
 288   print_stats(2, "Choose CSet",
 289     (_recorded_young_cset_choice_time_ms +
 290     _recorded_non_young_cset_choice_time_ms));
 291   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
 292   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
 293   print_stats(2, "Free CSet",
 294     (_recorded_young_free_cset_time_ms +
 295     _recorded_non_young_free_cset_time_ms));
 296   if (_cur_verify_after_time_ms > 0.0) {
 297     print_stats(2, "Verify After", _cur_verify_after_time_ms);
 298   }
 299 }