28 #include "opto/compile.hpp" |
28 #include "opto/compile.hpp" |
29 #include "opto/matcher.hpp" |
29 #include "opto/matcher.hpp" |
30 #include "opto/node.hpp" |
30 #include "opto/node.hpp" |
31 #include "opto/phase.hpp" |
31 #include "opto/phase.hpp" |
32 |
32 |
33 #ifndef PRODUCT |
|
34 int Phase::_total_bytes_compiled = 0; |
33 int Phase::_total_bytes_compiled = 0; |
35 |
34 |
36 elapsedTimer Phase::_t_totalCompilation; |
35 elapsedTimer Phase::_t_totalCompilation; |
37 elapsedTimer Phase::_t_methodCompilation; |
36 elapsedTimer Phase::_t_methodCompilation; |
38 elapsedTimer Phase::_t_stubCompilation; |
37 elapsedTimer Phase::_t_stubCompilation; |
39 #endif |
|
40 |
38 |
41 // The next timers used for LogCompilation |
39 // The counters to use for LogCompilation |
42 elapsedTimer Phase::_t_parser; |
40 elapsedTimer Phase::timers[max_phase_timers]; |
43 elapsedTimer Phase::_t_optimizer; |
|
44 elapsedTimer Phase::_t_escapeAnalysis; |
|
45 elapsedTimer Phase::_t_connectionGraph; |
|
46 elapsedTimer Phase::_t_idealLoop; |
|
47 elapsedTimer Phase::_t_ccp; |
|
48 elapsedTimer Phase::_t_matcher; |
|
49 elapsedTimer Phase::_t_registerAllocation; |
|
50 elapsedTimer Phase::_t_output; |
|
51 |
|
52 #ifndef PRODUCT |
|
53 elapsedTimer Phase::_t_graphReshaping; |
|
54 elapsedTimer Phase::_t_scheduler; |
|
55 elapsedTimer Phase::_t_blockOrdering; |
|
56 elapsedTimer Phase::_t_macroEliminate; |
|
57 elapsedTimer Phase::_t_macroExpand; |
|
58 elapsedTimer Phase::_t_peephole; |
|
59 elapsedTimer Phase::_t_postalloc_expand; |
|
60 elapsedTimer Phase::_t_codeGeneration; |
|
61 elapsedTimer Phase::_t_registerMethod; |
|
62 elapsedTimer Phase::_t_temporaryTimer1; |
|
63 elapsedTimer Phase::_t_temporaryTimer2; |
|
64 elapsedTimer Phase::_t_idealLoopVerify; |
|
65 |
|
66 // Subtimers for _t_optimizer |
|
67 elapsedTimer Phase::_t_iterGVN; |
|
68 elapsedTimer Phase::_t_iterGVN2; |
|
69 elapsedTimer Phase::_t_incrInline; |
|
70 |
|
71 // Subtimers for _t_registerAllocation |
|
72 elapsedTimer Phase::_t_ctorChaitin; |
|
73 elapsedTimer Phase::_t_buildIFGphysical; |
|
74 elapsedTimer Phase::_t_computeLive; |
|
75 elapsedTimer Phase::_t_regAllocSplit; |
|
76 elapsedTimer Phase::_t_postAllocCopyRemoval; |
|
77 elapsedTimer Phase::_t_fixupSpills; |
|
78 |
|
79 // Subtimers for _t_output |
|
80 elapsedTimer Phase::_t_instrSched; |
|
81 elapsedTimer Phase::_t_buildOopMaps; |
|
82 #endif |
|
83 |
41 |
84 //------------------------------Phase------------------------------------------ |
42 //------------------------------Phase------------------------------------------ |
85 Phase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) { |
43 Phase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) { |
86 // Poll for requests from shutdown mechanism to quiesce compiler (4448539, 4448544). |
44 // Poll for requests from shutdown mechanism to quiesce compiler (4448539, 4448544). |
87 // This is an effective place to poll, since the compiler is full of phases. |
45 // This is an effective place to poll, since the compiler is full of phases. |
88 // In particular, every inlining site uses a recursively created Parse phase. |
46 // In particular, every inlining site uses a recursively created Parse phase. |
89 CompileBroker::maybe_block(); |
47 CompileBroker::maybe_block(); |
90 } |
48 } |
91 |
49 |
92 #ifndef PRODUCT |
50 void Phase::print_timers() { |
93 static const double minimum_reported_time = 0.0001; // seconds |
51 tty->print_cr (" C2 Compile Time: %7.3f s", Phase::_t_totalCompilation.seconds()); |
94 static const double expected_method_compile_coverage = 0.97; // % |
52 tty->print_cr (" Parse: %7.3f s", timers[_t_parser].seconds()); |
95 static const double minimum_meaningful_method_compile = 2.00; // seconds |
|
96 |
53 |
97 void Phase::print_timers() { |
54 { |
98 tty->print_cr ("Accumulated compiler times:"); |
55 tty->print_cr (" Optimize: %7.3f s", timers[_t_optimizer].seconds()); |
99 tty->print_cr ("---------------------------"); |
|
100 tty->print_cr (" Total compilation: %3.3f sec.", Phase::_t_totalCompilation.seconds()); |
|
101 tty->print (" method compilation : %3.3f sec", Phase::_t_methodCompilation.seconds()); |
|
102 tty->print ("/%d bytes",_total_bytes_compiled); |
|
103 tty->print_cr (" (%3.0f bytes per sec) ", Phase::_total_bytes_compiled / Phase::_t_methodCompilation.seconds()); |
|
104 tty->print_cr (" stub compilation : %3.3f sec.", Phase::_t_stubCompilation.seconds()); |
|
105 tty->print_cr (" Phases:"); |
|
106 tty->print_cr (" parse : %3.3f sec", Phase::_t_parser.seconds()); |
|
107 tty->print_cr (" optimizer : %3.3f sec", Phase::_t_optimizer.seconds()); |
|
108 if( Verbose || WizardMode ) { |
|
109 if (DoEscapeAnalysis) { |
56 if (DoEscapeAnalysis) { |
110 // EA is part of Optimizer. |
57 // EA is part of Optimizer. |
111 tty->print_cr (" escape analysis: %3.3f sec", Phase::_t_escapeAnalysis.seconds()); |
58 tty->print_cr (" Escape Analysis: %7.3f s", timers[_t_escapeAnalysis].seconds()); |
112 tty->print_cr (" connection graph: %3.3f sec", Phase::_t_connectionGraph.seconds()); |
59 tty->print_cr (" Conn Graph: %7.3f s", timers[_t_connectionGraph].seconds()); |
113 tty->print_cr (" macroEliminate : %3.3f sec", Phase::_t_macroEliminate.seconds()); |
60 tty->print_cr (" Macro Eliminate: %7.3f s", timers[_t_macroEliminate].seconds()); |
114 } |
61 } |
115 tty->print_cr (" iterGVN : %3.3f sec", Phase::_t_iterGVN.seconds()); |
62 tty->print_cr (" GVN 1: %7.3f s", timers[_t_iterGVN].seconds()); |
116 tty->print_cr (" incrInline : %3.3f sec", Phase::_t_incrInline.seconds()); |
63 |
117 tty->print_cr (" idealLoop : %3.3f sec", Phase::_t_idealLoop.seconds()); |
64 { |
118 tty->print_cr (" idealLoopVerify: %3.3f sec", Phase::_t_idealLoopVerify.seconds()); |
65 tty->print_cr (" Incremental Inline: %7.3f s", timers[_t_incrInline].seconds()); |
119 tty->print_cr (" ccp : %3.3f sec", Phase::_t_ccp.seconds()); |
66 tty->print_cr (" IdealLoop: %7.3f s", timers[_t_incrInline_ideal].seconds()); |
120 tty->print_cr (" iterGVN2 : %3.3f sec", Phase::_t_iterGVN2.seconds()); |
67 tty->print_cr (" IGVN: %7.3f s", timers[_t_incrInline_igvn].seconds()); |
121 tty->print_cr (" macroExpand : %3.3f sec", Phase::_t_macroExpand.seconds()); |
68 tty->print_cr (" Inline: %7.3f s", timers[_t_incrInline_inline].seconds()); |
122 tty->print_cr (" graphReshape : %3.3f sec", Phase::_t_graphReshaping.seconds()); |
69 tty->print_cr (" Prune Useless: %7.3f s", timers[_t_incrInline_pru].seconds()); |
123 double optimizer_subtotal = Phase::_t_iterGVN.seconds() + Phase::_t_iterGVN2.seconds() + |
70 |
124 Phase::_t_escapeAnalysis.seconds() + Phase::_t_macroEliminate.seconds() + |
71 double other = timers[_t_incrInline].seconds() - |
125 Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() + |
72 (timers[_t_incrInline_ideal].seconds() + |
126 Phase::_t_macroExpand.seconds() + Phase::_t_graphReshaping.seconds(); |
73 timers[_t_incrInline_igvn].seconds() + |
127 double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0)); |
74 timers[_t_incrInline_inline].seconds() + |
128 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", optimizer_subtotal, percent_of_optimizer); |
75 timers[_t_incrInline_pru].seconds()); |
|
76 if (other > 0) { |
|
77 tty->print_cr(" Other: %7.3f s", other); |
|
78 } |
|
79 } |
|
80 tty->print_cr (" IdealLoop: %7.3f s", timers[_t_idealLoop].seconds()); |
|
81 tty->print_cr (" IdealLoop Verify: %7.3f s", timers[_t_idealLoopVerify].seconds()); |
|
82 tty->print_cr (" Cond Const Prop: %7.3f s", timers[_t_ccp].seconds()); |
|
83 tty->print_cr (" GVN 2: %7.3f s", timers[_t_iterGVN2].seconds()); |
|
84 tty->print_cr (" Macro Expand: %7.3f s", timers[_t_macroExpand].seconds()); |
|
85 tty->print_cr (" Graph Reshape: %7.3f s", timers[_t_graphReshaping].seconds()); |
|
86 |
|
87 double other = timers[_t_optimizer].seconds() - |
|
88 (timers[_t_escapeAnalysis].seconds() + |
|
89 timers[_t_iterGVN].seconds() + |
|
90 timers[_t_incrInline].seconds() + |
|
91 timers[_t_idealLoop].seconds() + |
|
92 timers[_t_idealLoopVerify].seconds() + |
|
93 timers[_t_ccp].seconds() + |
|
94 timers[_t_iterGVN2].seconds() + |
|
95 timers[_t_macroExpand].seconds() + |
|
96 timers[_t_graphReshaping].seconds()); |
|
97 if (other > 0) { |
|
98 tty->print_cr(" Other: %7.3f s", other); |
|
99 } |
129 } |
100 } |
130 tty->print_cr (" matcher : %3.3f sec", Phase::_t_matcher.seconds()); |
101 |
131 tty->print_cr (" scheduler : %3.3f sec", Phase::_t_scheduler.seconds()); |
102 tty->print_cr (" Matcher: %7.3f s", timers[_t_matcher].seconds()); |
132 tty->print_cr (" regalloc : %3.3f sec", Phase::_t_registerAllocation.seconds()); |
103 tty->print_cr (" Scheduler: %7.3f s", timers[_t_scheduler].seconds()); |
133 if( Verbose || WizardMode ) { |
104 |
134 tty->print_cr (" ctorChaitin : %3.3f sec", Phase::_t_ctorChaitin.seconds()); |
105 { |
135 tty->print_cr (" buildIFG : %3.3f sec", Phase::_t_buildIFGphysical.seconds()); |
106 tty->print_cr (" Regalloc: %7.3f s", timers[_t_registerAllocation].seconds()); |
136 tty->print_cr (" computeLive : %3.3f sec", Phase::_t_computeLive.seconds()); |
107 tty->print_cr (" Ctor Chaitin: %7.3f s", timers[_t_ctorChaitin].seconds()); |
137 tty->print_cr (" regAllocSplit : %3.3f sec", Phase::_t_regAllocSplit.seconds()); |
108 tty->print_cr (" Build IFG (virt): %7.3f s", timers[_t_buildIFGvirtual].seconds()); |
138 tty->print_cr (" postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds()); |
109 tty->print_cr (" Build IFG (phys): %7.3f s", timers[_t_buildIFGphysical].seconds()); |
139 tty->print_cr (" fixupSpills : %3.3f sec", Phase::_t_fixupSpills.seconds()); |
110 tty->print_cr (" Compute Liveness: %7.3f s", timers[_t_computeLive].seconds()); |
140 double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() + |
111 tty->print_cr (" Regalloc Split: %7.3f s", timers[_t_regAllocSplit].seconds()); |
141 Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() + |
112 tty->print_cr (" Postalloc Copy Rem: %7.3f s", timers[_t_postAllocCopyRemoval].seconds()); |
142 Phase::_t_regAllocSplit.seconds() + Phase::_t_fixupSpills.seconds() + |
113 tty->print_cr (" Fixup Spills: %7.3f s", timers[_t_fixupSpills].seconds()); |
143 Phase::_t_postAllocCopyRemoval.seconds(); |
114 tty->print_cr (" Compact: %7.3f s", timers[_t_chaitinCompact].seconds()); |
144 double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0)); |
115 tty->print_cr (" Coalesce 1: %7.3f s", timers[_t_chaitinCoalesce1].seconds()); |
145 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", regalloc_subtotal, percent_of_regalloc); |
116 tty->print_cr (" Coalesce 2: %7.3f s", timers[_t_chaitinCoalesce2].seconds()); |
|
117 tty->print_cr (" Coalesce 3: %7.3f s", timers[_t_chaitinCoalesce3].seconds()); |
|
118 tty->print_cr (" Cache LRG: %7.3f s", timers[_t_chaitinCacheLRG].seconds()); |
|
119 tty->print_cr (" Simplify: %7.3f s", timers[_t_chaitinSimplify].seconds()); |
|
120 tty->print_cr (" Select: %7.3f s", timers[_t_chaitinSelect].seconds()); |
|
121 |
|
122 double other = timers[_t_registerAllocation].seconds() - |
|
123 (timers[_t_ctorChaitin].seconds() + |
|
124 timers[_t_buildIFGvirtual].seconds() + |
|
125 timers[_t_buildIFGphysical].seconds() + |
|
126 timers[_t_computeLive].seconds() + |
|
127 timers[_t_regAllocSplit].seconds() + |
|
128 timers[_t_postAllocCopyRemoval].seconds() + |
|
129 timers[_t_fixupSpills].seconds() + |
|
130 timers[_t_chaitinCompact].seconds() + |
|
131 timers[_t_chaitinCoalesce1].seconds() + |
|
132 timers[_t_chaitinCoalesce2].seconds() + |
|
133 timers[_t_chaitinCoalesce3].seconds() + |
|
134 timers[_t_chaitinCacheLRG].seconds() + |
|
135 timers[_t_chaitinSimplify].seconds() + |
|
136 timers[_t_chaitinSelect].seconds()); |
|
137 |
|
138 if (other > 0) { |
|
139 tty->print_cr(" Other: %7.3f s", other); |
|
140 } |
146 } |
141 } |
147 tty->print_cr (" blockOrdering : %3.3f sec", Phase::_t_blockOrdering.seconds()); |
142 tty->print_cr (" Block Ordering: %7.3f s", timers[_t_blockOrdering].seconds()); |
148 tty->print_cr (" peephole : %3.3f sec", Phase::_t_peephole.seconds()); |
143 tty->print_cr (" Peephole: %7.3f s", timers[_t_peephole].seconds()); |
149 if (Matcher::require_postalloc_expand) { |
144 if (Matcher::require_postalloc_expand) { |
150 tty->print_cr (" postalloc_expand: %3.3f sec", Phase::_t_postalloc_expand.seconds()); |
145 tty->print_cr (" Postalloc Expand: %7.3f s", timers[_t_postalloc_expand].seconds()); |
151 } |
146 } |
152 tty->print_cr (" codeGen : %3.3f sec", Phase::_t_codeGeneration.seconds()); |
147 tty->print_cr (" Code Emission: %7.3f s", timers[_t_output].seconds()); |
153 tty->print_cr (" install_code : %3.3f sec", Phase::_t_registerMethod.seconds()); |
148 tty->print_cr (" Insn Scheduling: %7.3f s", timers[_t_instrSched].seconds()); |
154 tty->print_cr (" -------------- : ----------"); |
149 tty->print_cr (" Build OOP maps: %7.3f s", timers[_t_buildOopMaps].seconds()); |
155 double phase_subtotal = Phase::_t_parser.seconds() + |
150 tty->print_cr (" Code Installation: %7.3f s", timers[_t_registerMethod].seconds()); |
156 Phase::_t_optimizer.seconds() + Phase::_t_graphReshaping.seconds() + |
|
157 Phase::_t_matcher.seconds() + Phase::_t_scheduler.seconds() + |
|
158 Phase::_t_registerAllocation.seconds() + Phase::_t_blockOrdering.seconds() + |
|
159 Phase::_t_codeGeneration.seconds() + Phase::_t_registerMethod.seconds(); |
|
160 double percent_of_method_compile = ((phase_subtotal == 0.0) ? 0.0 : phase_subtotal / Phase::_t_methodCompilation.seconds()) * 100.0; |
|
161 // counters inside Compile::CodeGen include time for adapters and stubs |
|
162 // so phase-total can be greater than 100% |
|
163 tty->print_cr (" total : %3.3f sec, %3.2f %%", phase_subtotal, percent_of_method_compile); |
|
164 |
151 |
165 assert( percent_of_method_compile > expected_method_compile_coverage || |
152 if( timers[_t_temporaryTimer1].seconds() > 0 ) { |
166 phase_subtotal < minimum_meaningful_method_compile, |
153 tty->cr(); |
167 "Must account for method compilation"); |
154 tty->print_cr (" Temp Timer 1: %7.3f s", timers[_t_temporaryTimer1].seconds()); |
|
155 } |
|
156 if( timers[_t_temporaryTimer2].seconds() > 0 ) { |
|
157 tty->cr(); |
|
158 tty->print_cr (" Temp Timer 2: %7.3f s", timers[_t_temporaryTimer2].seconds()); |
|
159 } |
168 |
160 |
169 if( Phase::_t_temporaryTimer1.seconds() > minimum_reported_time ) { |
161 double other = Phase::_t_totalCompilation.seconds() - |
170 tty->cr(); |
162 (timers[_t_parser].seconds() + |
171 tty->print_cr (" temporaryTimer1: %3.3f sec", Phase::_t_temporaryTimer1.seconds()); |
163 timers[_t_optimizer].seconds() + |
172 } |
164 timers[_t_matcher].seconds() + |
173 if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) { |
165 timers[_t_scheduler].seconds() + |
174 tty->cr(); |
166 timers[_t_registerAllocation].seconds() + |
175 tty->print_cr (" temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds()); |
167 timers[_t_blockOrdering].seconds() + |
176 } |
168 timers[_t_peephole].seconds() + |
177 tty->print_cr (" output : %3.3f sec", Phase::_t_output.seconds()); |
169 timers[_t_postalloc_expand].seconds() + |
178 tty->print_cr (" isched : %3.3f sec", Phase::_t_instrSched.seconds()); |
170 timers[_t_output].seconds() + |
179 tty->print_cr (" bldOopMaps : %3.3f sec", Phase::_t_buildOopMaps.seconds()); |
171 timers[_t_registerMethod].seconds() + |
|
172 timers[_t_temporaryTimer1].seconds() + |
|
173 timers[_t_temporaryTimer2].seconds()); |
|
174 if (other > 0) { |
|
175 tty->print_cr(" Other: %7.3f s", other); |
|
176 } |
|
177 |
180 } |
178 } |
181 #endif |
|