150 template <class T> 151 void WorkerDataArray<T>::verify() { 152 for (uint i = 0; i < _length; i++) { 153 assert(_data[i] != _uninitialized, 154 err_msg("Invalid data for worker %u, data: %lf, uninitialized: %lf", 155 i, (double)_data[i], (double)_uninitialized)); 156 } 157 } 158 159 #endif 160 161 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : 162 _max_gc_threads(max_gc_threads), 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_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"), 170 _last_strong_code_root_mark_times_ms(_max_gc_threads, "%.1lf"), 171 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"), 172 _last_termination_times_ms(_max_gc_threads, "%.1lf"), 173 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT), 174 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false), 175 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"), 176 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"), 177 _last_redirty_logged_cards_time_ms(_max_gc_threads, "%.1lf"), 178 _last_redirty_logged_cards_processed_cards(_max_gc_threads, SIZE_FORMAT), 179 _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"), 180 _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf") 181 { 182 assert(max_gc_threads > 0, "Must have some GC threads"); 183 } 184 185 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { 186 assert(active_gc_threads > 0, "The number of threads must be > 0"); 187 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads"); 188 _active_gc_threads = active_gc_threads; 189 190 _last_gc_worker_start_times_ms.reset(); 191 _last_ext_root_scan_times_ms.reset(); 192 _last_satb_filtering_times_ms.reset(); 193 _last_update_rs_times_ms.reset(); 194 _last_update_rs_processed_buffers.reset(); 195 _last_scan_rs_times_ms.reset(); 196 _last_strong_code_root_scan_times_ms.reset(); 197 _last_strong_code_root_mark_times_ms.reset(); 198 _last_obj_copy_times_ms.reset(); 199 _last_termination_times_ms.reset(); 200 _last_termination_attempts.reset(); 201 _last_gc_worker_end_times_ms.reset(); 202 _last_gc_worker_times_ms.reset(); 203 _last_gc_worker_other_times_ms.reset(); 204 205 _last_redirty_logged_cards_time_ms.reset(); 206 _last_redirty_logged_cards_processed_cards.reset(); 207 208 } 209 210 void G1GCPhaseTimes::note_gc_end() { 211 _last_gc_worker_start_times_ms.verify(); 212 _last_ext_root_scan_times_ms.verify(); 213 _last_satb_filtering_times_ms.verify(); 214 _last_update_rs_times_ms.verify(); 215 _last_update_rs_processed_buffers.verify(); 216 _last_scan_rs_times_ms.verify(); 217 _last_strong_code_root_scan_times_ms.verify(); 218 _last_strong_code_root_mark_times_ms.verify(); 219 _last_obj_copy_times_ms.verify(); 220 _last_termination_times_ms.verify(); 221 _last_termination_attempts.verify(); 222 _last_gc_worker_end_times_ms.verify(); 223 224 for (uint i = 0; i < _active_gc_threads; i++) { 225 double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i); 226 _last_gc_worker_times_ms.set(i, worker_time); 227 228 double worker_known_time = _last_ext_root_scan_times_ms.get(i) + 229 _last_satb_filtering_times_ms.get(i) + 230 _last_update_rs_times_ms.get(i) + 231 _last_scan_rs_times_ms.get(i) + 232 _last_strong_code_root_scan_times_ms.get(i) + 233 _last_strong_code_root_mark_times_ms.get(i) + 234 _last_obj_copy_times_ms.get(i) + 235 _last_termination_times_ms.get(i); 236 237 double worker_other_time = worker_time - worker_known_time; 238 _last_gc_worker_other_times_ms.set(i, worker_other_time); 239 } 240 241 _last_gc_worker_times_ms.verify(); 242 _last_gc_worker_other_times_ms.verify(); 243 244 _last_redirty_logged_cards_time_ms.verify(); 245 _last_redirty_logged_cards_processed_cards.verify(); 246 } 247 248 void G1GCPhaseTimes::note_string_dedup_fixup_start() { 249 _cur_string_dedup_queue_fixup_worker_times_ms.reset(); 250 _cur_string_dedup_table_fixup_worker_times_ms.reset(); 251 } 252 253 void G1GCPhaseTimes::note_string_dedup_fixup_end() { 285 } 286 287 // Subtract the time taken to clean the card table from the 288 // current value of "other time" 289 misc_time_ms += _cur_clear_ct_time_ms; 290 291 return misc_time_ms; 292 } 293 294 void G1GCPhaseTimes::print(double pause_time_sec) { 295 if (_root_region_scan_wait_time_ms > 0.0) { 296 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); 297 } 298 if (G1CollectedHeap::use_parallel_gc_threads()) { 299 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); 300 _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)"); 301 _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)"); 302 if (_last_satb_filtering_times_ms.sum() > 0.0) { 303 _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)"); 304 } 305 if (_last_strong_code_root_mark_times_ms.sum() > 0.0) { 306 _last_strong_code_root_mark_times_ms.print(2, "Code Root Marking (ms)"); 307 } 308 _last_update_rs_times_ms.print(2, "Update RS (ms)"); 309 _last_update_rs_processed_buffers.print(3, "Processed Buffers"); 310 _last_scan_rs_times_ms.print(2, "Scan RS (ms)"); 311 _last_strong_code_root_scan_times_ms.print(2, "Code Root Scanning (ms)"); 312 _last_obj_copy_times_ms.print(2, "Object Copy (ms)"); 313 _last_termination_times_ms.print(2, "Termination (ms)"); 314 if (G1Log::finest()) { 315 _last_termination_attempts.print(3, "Termination Attempts"); 316 } 317 _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)"); 318 _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)"); 319 _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)"); 320 } else { 321 _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)"); 322 if (_last_satb_filtering_times_ms.sum() > 0.0) { 323 _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)"); 324 } 325 if (_last_strong_code_root_mark_times_ms.sum() > 0.0) { 326 _last_strong_code_root_mark_times_ms.print(1, "Code Root Marking (ms)"); 327 } 328 _last_update_rs_times_ms.print(1, "Update RS (ms)"); 329 _last_update_rs_processed_buffers.print(2, "Processed Buffers"); 330 _last_scan_rs_times_ms.print(1, "Scan RS (ms)"); 331 _last_strong_code_root_scan_times_ms.print(1, "Code Root Scanning (ms)"); 332 _last_obj_copy_times_ms.print(1, "Object Copy (ms)"); 333 } 334 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); 335 print_stats(1, "Code Root Migration", _cur_strong_code_root_migration_time_ms); 336 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms); 337 if (G1StringDedup::is_enabled()) { 338 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads); 339 _cur_string_dedup_queue_fixup_worker_times_ms.print(2, "Queue Fixup (ms)"); 340 _cur_string_dedup_table_fixup_worker_times_ms.print(2, "Table Fixup (ms)"); 341 } 342 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); 343 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms(); 344 print_stats(1, "Other", misc_time_ms); 345 if (_cur_verify_before_time_ms > 0.0) { 346 print_stats(2, "Verify Before", _cur_verify_before_time_ms); | 150 template <class T> 151 void WorkerDataArray<T>::verify() { 152 for (uint i = 0; i < _length; i++) { 153 assert(_data[i] != _uninitialized, 154 err_msg("Invalid data for worker %u, data: %lf, uninitialized: %lf", 155 i, (double)_data[i], (double)_uninitialized)); 156 } 157 } 158 159 #endif 160 161 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : 162 _max_gc_threads(max_gc_threads), 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_strong_code_root_scan_times_ms(_max_gc_threads, "%.1lf"), 170 _last_obj_copy_times_ms(_max_gc_threads, "%.1lf"), 171 _last_termination_times_ms(_max_gc_threads, "%.1lf"), 172 _last_termination_attempts(_max_gc_threads, SIZE_FORMAT), 173 _last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false), 174 _last_gc_worker_times_ms(_max_gc_threads, "%.1lf"), 175 _last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf"), 176 _last_redirty_logged_cards_time_ms(_max_gc_threads, "%.1lf"), 177 _last_redirty_logged_cards_processed_cards(_max_gc_threads, SIZE_FORMAT), 178 _cur_string_dedup_queue_fixup_worker_times_ms(_max_gc_threads, "%.1lf"), 179 _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf") 180 { 181 assert(max_gc_threads > 0, "Must have some GC threads"); 182 } 183 184 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { 185 assert(active_gc_threads > 0, "The number of threads must be > 0"); 186 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads"); 187 _active_gc_threads = active_gc_threads; 188 189 _last_gc_worker_start_times_ms.reset(); 190 _last_ext_root_scan_times_ms.reset(); 191 _last_satb_filtering_times_ms.reset(); 192 _last_update_rs_times_ms.reset(); 193 _last_update_rs_processed_buffers.reset(); 194 _last_scan_rs_times_ms.reset(); 195 _last_strong_code_root_scan_times_ms.reset(); 196 _last_obj_copy_times_ms.reset(); 197 _last_termination_times_ms.reset(); 198 _last_termination_attempts.reset(); 199 _last_gc_worker_end_times_ms.reset(); 200 _last_gc_worker_times_ms.reset(); 201 _last_gc_worker_other_times_ms.reset(); 202 203 _last_redirty_logged_cards_time_ms.reset(); 204 _last_redirty_logged_cards_processed_cards.reset(); 205 206 } 207 208 void G1GCPhaseTimes::note_gc_end() { 209 _last_gc_worker_start_times_ms.verify(); 210 _last_ext_root_scan_times_ms.verify(); 211 _last_satb_filtering_times_ms.verify(); 212 _last_update_rs_times_ms.verify(); 213 _last_update_rs_processed_buffers.verify(); 214 _last_scan_rs_times_ms.verify(); 215 _last_strong_code_root_scan_times_ms.verify(); 216 _last_obj_copy_times_ms.verify(); 217 _last_termination_times_ms.verify(); 218 _last_termination_attempts.verify(); 219 _last_gc_worker_end_times_ms.verify(); 220 221 for (uint i = 0; i < _active_gc_threads; i++) { 222 double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i); 223 _last_gc_worker_times_ms.set(i, worker_time); 224 225 double worker_known_time = _last_ext_root_scan_times_ms.get(i) + 226 _last_satb_filtering_times_ms.get(i) + 227 _last_update_rs_times_ms.get(i) + 228 _last_scan_rs_times_ms.get(i) + 229 _last_strong_code_root_scan_times_ms.get(i) + 230 _last_obj_copy_times_ms.get(i) + 231 _last_termination_times_ms.get(i); 232 233 double worker_other_time = worker_time - worker_known_time; 234 _last_gc_worker_other_times_ms.set(i, worker_other_time); 235 } 236 237 _last_gc_worker_times_ms.verify(); 238 _last_gc_worker_other_times_ms.verify(); 239 240 _last_redirty_logged_cards_time_ms.verify(); 241 _last_redirty_logged_cards_processed_cards.verify(); 242 } 243 244 void G1GCPhaseTimes::note_string_dedup_fixup_start() { 245 _cur_string_dedup_queue_fixup_worker_times_ms.reset(); 246 _cur_string_dedup_table_fixup_worker_times_ms.reset(); 247 } 248 249 void G1GCPhaseTimes::note_string_dedup_fixup_end() { 281 } 282 283 // Subtract the time taken to clean the card table from the 284 // current value of "other time" 285 misc_time_ms += _cur_clear_ct_time_ms; 286 287 return misc_time_ms; 288 } 289 290 void G1GCPhaseTimes::print(double pause_time_sec) { 291 if (_root_region_scan_wait_time_ms > 0.0) { 292 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms); 293 } 294 if (G1CollectedHeap::use_parallel_gc_threads()) { 295 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); 296 _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)"); 297 _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)"); 298 if (_last_satb_filtering_times_ms.sum() > 0.0) { 299 _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)"); 300 } 301 _last_update_rs_times_ms.print(2, "Update RS (ms)"); 302 _last_update_rs_processed_buffers.print(3, "Processed Buffers"); 303 _last_scan_rs_times_ms.print(2, "Scan RS (ms)"); 304 _last_strong_code_root_scan_times_ms.print(2, "Code Root Scanning (ms)"); 305 _last_obj_copy_times_ms.print(2, "Object Copy (ms)"); 306 _last_termination_times_ms.print(2, "Termination (ms)"); 307 if (G1Log::finest()) { 308 _last_termination_attempts.print(3, "Termination Attempts"); 309 } 310 _last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)"); 311 _last_gc_worker_times_ms.print(2, "GC Worker Total (ms)"); 312 _last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)"); 313 } else { 314 _last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)"); 315 if (_last_satb_filtering_times_ms.sum() > 0.0) { 316 _last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)"); 317 } 318 _last_update_rs_times_ms.print(1, "Update RS (ms)"); 319 _last_update_rs_processed_buffers.print(2, "Processed Buffers"); 320 _last_scan_rs_times_ms.print(1, "Scan RS (ms)"); 321 _last_strong_code_root_scan_times_ms.print(1, "Code Root Scanning (ms)"); 322 _last_obj_copy_times_ms.print(1, "Object Copy (ms)"); 323 } 324 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms); 325 print_stats(1, "Code Root Migration", _cur_strong_code_root_migration_time_ms); 326 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms); 327 if (G1StringDedup::is_enabled()) { 328 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads); 329 _cur_string_dedup_queue_fixup_worker_times_ms.print(2, "Queue Fixup (ms)"); 330 _cur_string_dedup_table_fixup_worker_times_ms.print(2, "Table Fixup (ms)"); 331 } 332 print_stats(1, "Clear CT", _cur_clear_ct_time_ms); 333 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms(); 334 print_stats(1, "Other", misc_time_ms); 335 if (_cur_verify_before_time_ms > 0.0) { 336 print_stats(2, "Verify Before", _cur_verify_before_time_ms); |