--- a/hotspot/src/share/vm/opto/phase.cpp Mon Sep 29 08:40:51 2014 +0200
+++ b/hotspot/src/share/vm/opto/phase.cpp Thu Sep 25 12:10:57 2014 +0400
@@ -30,56 +30,14 @@
#include "opto/node.hpp"
#include "opto/phase.hpp"
-#ifndef PRODUCT
int Phase::_total_bytes_compiled = 0;
elapsedTimer Phase::_t_totalCompilation;
elapsedTimer Phase::_t_methodCompilation;
elapsedTimer Phase::_t_stubCompilation;
-#endif
-// The next timers used for LogCompilation
-elapsedTimer Phase::_t_parser;
-elapsedTimer Phase::_t_optimizer;
-elapsedTimer Phase::_t_escapeAnalysis;
-elapsedTimer Phase::_t_connectionGraph;
-elapsedTimer Phase::_t_idealLoop;
-elapsedTimer Phase::_t_ccp;
-elapsedTimer Phase::_t_matcher;
-elapsedTimer Phase::_t_registerAllocation;
-elapsedTimer Phase::_t_output;
-
-#ifndef PRODUCT
-elapsedTimer Phase::_t_graphReshaping;
-elapsedTimer Phase::_t_scheduler;
-elapsedTimer Phase::_t_blockOrdering;
-elapsedTimer Phase::_t_macroEliminate;
-elapsedTimer Phase::_t_macroExpand;
-elapsedTimer Phase::_t_peephole;
-elapsedTimer Phase::_t_postalloc_expand;
-elapsedTimer Phase::_t_codeGeneration;
-elapsedTimer Phase::_t_registerMethod;
-elapsedTimer Phase::_t_temporaryTimer1;
-elapsedTimer Phase::_t_temporaryTimer2;
-elapsedTimer Phase::_t_idealLoopVerify;
-
-// Subtimers for _t_optimizer
-elapsedTimer Phase::_t_iterGVN;
-elapsedTimer Phase::_t_iterGVN2;
-elapsedTimer Phase::_t_incrInline;
-
-// Subtimers for _t_registerAllocation
-elapsedTimer Phase::_t_ctorChaitin;
-elapsedTimer Phase::_t_buildIFGphysical;
-elapsedTimer Phase::_t_computeLive;
-elapsedTimer Phase::_t_regAllocSplit;
-elapsedTimer Phase::_t_postAllocCopyRemoval;
-elapsedTimer Phase::_t_fixupSpills;
-
-// Subtimers for _t_output
-elapsedTimer Phase::_t_instrSched;
-elapsedTimer Phase::_t_buildOopMaps;
-#endif
+// The counters to use for LogCompilation
+elapsedTimer Phase::timers[max_phase_timers];
//------------------------------Phase------------------------------------------
Phase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) {
@@ -89,93 +47,132 @@
CompileBroker::maybe_block();
}
-#ifndef PRODUCT
-static const double minimum_reported_time = 0.0001; // seconds
-static const double expected_method_compile_coverage = 0.97; // %
-static const double minimum_meaningful_method_compile = 2.00; // seconds
+void Phase::print_timers() {
+ tty->print_cr (" C2 Compile Time: %7.3f s", Phase::_t_totalCompilation.seconds());
+ tty->print_cr (" Parse: %7.3f s", timers[_t_parser].seconds());
-void Phase::print_timers() {
- tty->print_cr ("Accumulated compiler times:");
- tty->print_cr ("---------------------------");
- tty->print_cr (" Total compilation: %3.3f sec.", Phase::_t_totalCompilation.seconds());
- tty->print (" method compilation : %3.3f sec", Phase::_t_methodCompilation.seconds());
- tty->print ("/%d bytes",_total_bytes_compiled);
- tty->print_cr (" (%3.0f bytes per sec) ", Phase::_total_bytes_compiled / Phase::_t_methodCompilation.seconds());
- tty->print_cr (" stub compilation : %3.3f sec.", Phase::_t_stubCompilation.seconds());
- tty->print_cr (" Phases:");
- tty->print_cr (" parse : %3.3f sec", Phase::_t_parser.seconds());
- tty->print_cr (" optimizer : %3.3f sec", Phase::_t_optimizer.seconds());
- if( Verbose || WizardMode ) {
+ {
+ tty->print_cr (" Optimize: %7.3f s", timers[_t_optimizer].seconds());
if (DoEscapeAnalysis) {
// EA is part of Optimizer.
- tty->print_cr (" escape analysis: %3.3f sec", Phase::_t_escapeAnalysis.seconds());
- tty->print_cr (" connection graph: %3.3f sec", Phase::_t_connectionGraph.seconds());
- tty->print_cr (" macroEliminate : %3.3f sec", Phase::_t_macroEliminate.seconds());
+ tty->print_cr (" Escape Analysis: %7.3f s", timers[_t_escapeAnalysis].seconds());
+ tty->print_cr (" Conn Graph: %7.3f s", timers[_t_connectionGraph].seconds());
+ tty->print_cr (" Macro Eliminate: %7.3f s", timers[_t_macroEliminate].seconds());
}
- tty->print_cr (" iterGVN : %3.3f sec", Phase::_t_iterGVN.seconds());
- tty->print_cr (" incrInline : %3.3f sec", Phase::_t_incrInline.seconds());
- tty->print_cr (" idealLoop : %3.3f sec", Phase::_t_idealLoop.seconds());
- tty->print_cr (" idealLoopVerify: %3.3f sec", Phase::_t_idealLoopVerify.seconds());
- tty->print_cr (" ccp : %3.3f sec", Phase::_t_ccp.seconds());
- tty->print_cr (" iterGVN2 : %3.3f sec", Phase::_t_iterGVN2.seconds());
- tty->print_cr (" macroExpand : %3.3f sec", Phase::_t_macroExpand.seconds());
- tty->print_cr (" graphReshape : %3.3f sec", Phase::_t_graphReshaping.seconds());
- double optimizer_subtotal = Phase::_t_iterGVN.seconds() + Phase::_t_iterGVN2.seconds() +
- Phase::_t_escapeAnalysis.seconds() + Phase::_t_macroEliminate.seconds() +
- Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() +
- Phase::_t_macroExpand.seconds() + Phase::_t_graphReshaping.seconds();
- double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0));
- tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", optimizer_subtotal, percent_of_optimizer);
- }
- tty->print_cr (" matcher : %3.3f sec", Phase::_t_matcher.seconds());
- tty->print_cr (" scheduler : %3.3f sec", Phase::_t_scheduler.seconds());
- tty->print_cr (" regalloc : %3.3f sec", Phase::_t_registerAllocation.seconds());
- if( Verbose || WizardMode ) {
- tty->print_cr (" ctorChaitin : %3.3f sec", Phase::_t_ctorChaitin.seconds());
- tty->print_cr (" buildIFG : %3.3f sec", Phase::_t_buildIFGphysical.seconds());
- tty->print_cr (" computeLive : %3.3f sec", Phase::_t_computeLive.seconds());
- tty->print_cr (" regAllocSplit : %3.3f sec", Phase::_t_regAllocSplit.seconds());
- tty->print_cr (" postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds());
- tty->print_cr (" fixupSpills : %3.3f sec", Phase::_t_fixupSpills.seconds());
- double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() +
- Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() +
- Phase::_t_regAllocSplit.seconds() + Phase::_t_fixupSpills.seconds() +
- Phase::_t_postAllocCopyRemoval.seconds();
- double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0));
- tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", regalloc_subtotal, percent_of_regalloc);
+ tty->print_cr (" GVN 1: %7.3f s", timers[_t_iterGVN].seconds());
+
+ {
+ tty->print_cr (" Incremental Inline: %7.3f s", timers[_t_incrInline].seconds());
+ tty->print_cr (" IdealLoop: %7.3f s", timers[_t_incrInline_ideal].seconds());
+ tty->print_cr (" IGVN: %7.3f s", timers[_t_incrInline_igvn].seconds());
+ tty->print_cr (" Inline: %7.3f s", timers[_t_incrInline_inline].seconds());
+ tty->print_cr (" Prune Useless: %7.3f s", timers[_t_incrInline_pru].seconds());
+
+ double other = timers[_t_incrInline].seconds() -
+ (timers[_t_incrInline_ideal].seconds() +
+ timers[_t_incrInline_igvn].seconds() +
+ timers[_t_incrInline_inline].seconds() +
+ timers[_t_incrInline_pru].seconds());
+ if (other > 0) {
+ tty->print_cr(" Other: %7.3f s", other);
+ }
+ }
+ tty->print_cr (" IdealLoop: %7.3f s", timers[_t_idealLoop].seconds());
+ tty->print_cr (" IdealLoop Verify: %7.3f s", timers[_t_idealLoopVerify].seconds());
+ tty->print_cr (" Cond Const Prop: %7.3f s", timers[_t_ccp].seconds());
+ tty->print_cr (" GVN 2: %7.3f s", timers[_t_iterGVN2].seconds());
+ tty->print_cr (" Macro Expand: %7.3f s", timers[_t_macroExpand].seconds());
+ tty->print_cr (" Graph Reshape: %7.3f s", timers[_t_graphReshaping].seconds());
+
+ double other = timers[_t_optimizer].seconds() -
+ (timers[_t_escapeAnalysis].seconds() +
+ timers[_t_iterGVN].seconds() +
+ timers[_t_incrInline].seconds() +
+ timers[_t_idealLoop].seconds() +
+ timers[_t_idealLoopVerify].seconds() +
+ timers[_t_ccp].seconds() +
+ timers[_t_iterGVN2].seconds() +
+ timers[_t_macroExpand].seconds() +
+ timers[_t_graphReshaping].seconds());
+ if (other > 0) {
+ tty->print_cr(" Other: %7.3f s", other);
+ }
}
- tty->print_cr (" blockOrdering : %3.3f sec", Phase::_t_blockOrdering.seconds());
- tty->print_cr (" peephole : %3.3f sec", Phase::_t_peephole.seconds());
- if (Matcher::require_postalloc_expand) {
- tty->print_cr (" postalloc_expand: %3.3f sec", Phase::_t_postalloc_expand.seconds());
- }
- tty->print_cr (" codeGen : %3.3f sec", Phase::_t_codeGeneration.seconds());
- tty->print_cr (" install_code : %3.3f sec", Phase::_t_registerMethod.seconds());
- tty->print_cr (" -------------- : ----------");
- double phase_subtotal = Phase::_t_parser.seconds() +
- Phase::_t_optimizer.seconds() + Phase::_t_graphReshaping.seconds() +
- Phase::_t_matcher.seconds() + Phase::_t_scheduler.seconds() +
- Phase::_t_registerAllocation.seconds() + Phase::_t_blockOrdering.seconds() +
- Phase::_t_codeGeneration.seconds() + Phase::_t_registerMethod.seconds();
- double percent_of_method_compile = ((phase_subtotal == 0.0) ? 0.0 : phase_subtotal / Phase::_t_methodCompilation.seconds()) * 100.0;
- // counters inside Compile::CodeGen include time for adapters and stubs
- // so phase-total can be greater than 100%
- tty->print_cr (" total : %3.3f sec, %3.2f %%", phase_subtotal, percent_of_method_compile);
+
+ tty->print_cr (" Matcher: %7.3f s", timers[_t_matcher].seconds());
+ tty->print_cr (" Scheduler: %7.3f s", timers[_t_scheduler].seconds());
+
+ {
+ tty->print_cr (" Regalloc: %7.3f s", timers[_t_registerAllocation].seconds());
+ tty->print_cr (" Ctor Chaitin: %7.3f s", timers[_t_ctorChaitin].seconds());
+ tty->print_cr (" Build IFG (virt): %7.3f s", timers[_t_buildIFGvirtual].seconds());
+ tty->print_cr (" Build IFG (phys): %7.3f s", timers[_t_buildIFGphysical].seconds());
+ tty->print_cr (" Compute Liveness: %7.3f s", timers[_t_computeLive].seconds());
+ tty->print_cr (" Regalloc Split: %7.3f s", timers[_t_regAllocSplit].seconds());
+ tty->print_cr (" Postalloc Copy Rem: %7.3f s", timers[_t_postAllocCopyRemoval].seconds());
+ tty->print_cr (" Fixup Spills: %7.3f s", timers[_t_fixupSpills].seconds());
+ tty->print_cr (" Compact: %7.3f s", timers[_t_chaitinCompact].seconds());
+ tty->print_cr (" Coalesce 1: %7.3f s", timers[_t_chaitinCoalesce1].seconds());
+ tty->print_cr (" Coalesce 2: %7.3f s", timers[_t_chaitinCoalesce2].seconds());
+ tty->print_cr (" Coalesce 3: %7.3f s", timers[_t_chaitinCoalesce3].seconds());
+ tty->print_cr (" Cache LRG: %7.3f s", timers[_t_chaitinCacheLRG].seconds());
+ tty->print_cr (" Simplify: %7.3f s", timers[_t_chaitinSimplify].seconds());
+ tty->print_cr (" Select: %7.3f s", timers[_t_chaitinSelect].seconds());
+
+ double other = timers[_t_registerAllocation].seconds() -
+ (timers[_t_ctorChaitin].seconds() +
+ timers[_t_buildIFGvirtual].seconds() +
+ timers[_t_buildIFGphysical].seconds() +
+ timers[_t_computeLive].seconds() +
+ timers[_t_regAllocSplit].seconds() +
+ timers[_t_postAllocCopyRemoval].seconds() +
+ timers[_t_fixupSpills].seconds() +
+ timers[_t_chaitinCompact].seconds() +
+ timers[_t_chaitinCoalesce1].seconds() +
+ timers[_t_chaitinCoalesce2].seconds() +
+ timers[_t_chaitinCoalesce3].seconds() +
+ timers[_t_chaitinCacheLRG].seconds() +
+ timers[_t_chaitinSimplify].seconds() +
+ timers[_t_chaitinSelect].seconds());
- assert( percent_of_method_compile > expected_method_compile_coverage ||
- phase_subtotal < minimum_meaningful_method_compile,
- "Must account for method compilation");
+ if (other > 0) {
+ tty->print_cr(" Other: %7.3f s", other);
+ }
+ }
+ tty->print_cr (" Block Ordering: %7.3f s", timers[_t_blockOrdering].seconds());
+ tty->print_cr (" Peephole: %7.3f s", timers[_t_peephole].seconds());
+ if (Matcher::require_postalloc_expand) {
+ tty->print_cr (" Postalloc Expand: %7.3f s", timers[_t_postalloc_expand].seconds());
+ }
+ tty->print_cr (" Code Emission: %7.3f s", timers[_t_output].seconds());
+ tty->print_cr (" Insn Scheduling: %7.3f s", timers[_t_instrSched].seconds());
+ tty->print_cr (" Build OOP maps: %7.3f s", timers[_t_buildOopMaps].seconds());
+ tty->print_cr (" Code Installation: %7.3f s", timers[_t_registerMethod].seconds());
- if( Phase::_t_temporaryTimer1.seconds() > minimum_reported_time ) {
+ if( timers[_t_temporaryTimer1].seconds() > 0 ) {
tty->cr();
- tty->print_cr (" temporaryTimer1: %3.3f sec", Phase::_t_temporaryTimer1.seconds());
+ tty->print_cr (" Temp Timer 1: %7.3f s", timers[_t_temporaryTimer1].seconds());
}
- if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) {
+ if( timers[_t_temporaryTimer2].seconds() > 0 ) {
tty->cr();
- tty->print_cr (" temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds());
+ tty->print_cr (" Temp Timer 2: %7.3f s", timers[_t_temporaryTimer2].seconds());
}
- tty->print_cr (" output : %3.3f sec", Phase::_t_output.seconds());
- tty->print_cr (" isched : %3.3f sec", Phase::_t_instrSched.seconds());
- tty->print_cr (" bldOopMaps : %3.3f sec", Phase::_t_buildOopMaps.seconds());
+
+ double other = Phase::_t_totalCompilation.seconds() -
+ (timers[_t_parser].seconds() +
+ timers[_t_optimizer].seconds() +
+ timers[_t_matcher].seconds() +
+ timers[_t_scheduler].seconds() +
+ timers[_t_registerAllocation].seconds() +
+ timers[_t_blockOrdering].seconds() +
+ timers[_t_peephole].seconds() +
+ timers[_t_postalloc_expand].seconds() +
+ timers[_t_output].seconds() +
+ timers[_t_registerMethod].seconds() +
+ timers[_t_temporaryTimer1].seconds() +
+ timers[_t_temporaryTimer2].seconds());
+ if (other > 0) {
+ tty->print_cr(" Other: %7.3f s", other);
+ }
+
}
-#endif