86 |
87 |
87 void Phase::print_timers() { |
88 void Phase::print_timers() { |
88 tty->print_cr ("Accumulated compiler times:"); |
89 tty->print_cr ("Accumulated compiler times:"); |
89 tty->print_cr ("---------------------------"); |
90 tty->print_cr ("---------------------------"); |
90 tty->print_cr (" Total compilation: %3.3f sec.", Phase::_t_totalCompilation.seconds()); |
91 tty->print_cr (" Total compilation: %3.3f sec.", Phase::_t_totalCompilation.seconds()); |
91 tty->print (" method compilation : %3.3f sec", Phase::_t_methodCompilation.seconds()); |
92 tty->print (" method compilation : %3.3f sec", Phase::_t_methodCompilation.seconds()); |
92 tty->print ("/%d bytes",_total_bytes_compiled); |
93 tty->print ("/%d bytes",_total_bytes_compiled); |
93 tty->print_cr (" (%3.0f bytes per sec) ", Phase::_total_bytes_compiled / Phase::_t_methodCompilation.seconds()); |
94 tty->print_cr (" (%3.0f bytes per sec) ", Phase::_total_bytes_compiled / Phase::_t_methodCompilation.seconds()); |
94 tty->print_cr (" stub compilation : %3.3f sec.", Phase::_t_stubCompilation.seconds()); |
95 tty->print_cr (" stub compilation : %3.3f sec.", Phase::_t_stubCompilation.seconds()); |
95 tty->print_cr (" Phases:"); |
96 tty->print_cr (" Phases:"); |
96 tty->print_cr (" parse : %3.3f sec", Phase::_t_parser.seconds()); |
97 tty->print_cr (" parse : %3.3f sec", Phase::_t_parser.seconds()); |
97 if (DoEscapeAnalysis) { |
98 if (DoEscapeAnalysis) { |
98 tty->print_cr (" escape analysis : %3.3f sec", Phase::_t_escapeAnalysis.seconds()); |
99 tty->print_cr (" escape analysis : %3.3f sec", Phase::_t_escapeAnalysis.seconds()); |
99 } |
100 } |
100 tty->print_cr (" optimizer : %3.3f sec", Phase::_t_optimizer.seconds()); |
101 tty->print_cr (" optimizer : %3.3f sec", Phase::_t_optimizer.seconds()); |
101 if( Verbose || WizardMode ) { |
102 if( Verbose || WizardMode ) { |
102 tty->print_cr (" iterGVN : %3.3f sec", Phase::_t_iterGVN.seconds()); |
103 tty->print_cr (" iterGVN : %3.3f sec", Phase::_t_iterGVN.seconds()); |
103 tty->print_cr (" idealLoop : %3.3f sec", Phase::_t_idealLoop.seconds()); |
104 tty->print_cr (" idealLoop : %3.3f sec", Phase::_t_idealLoop.seconds()); |
104 tty->print_cr (" ccp : %3.3f sec", Phase::_t_ccp.seconds()); |
105 tty->print_cr (" idealLoopVerify: %3.3f sec", Phase::_t_idealLoopVerify.seconds()); |
105 tty->print_cr (" iterGVN2 : %3.3f sec", Phase::_t_iterGVN2.seconds()); |
106 tty->print_cr (" ccp : %3.3f sec", Phase::_t_ccp.seconds()); |
106 tty->print_cr (" graphReshape : %3.3f sec", Phase::_t_graphReshaping.seconds()); |
107 tty->print_cr (" iterGVN2 : %3.3f sec", Phase::_t_iterGVN2.seconds()); |
|
108 tty->print_cr (" graphReshape : %3.3f sec", Phase::_t_graphReshaping.seconds()); |
107 double optimizer_subtotal = Phase::_t_iterGVN.seconds() + |
109 double optimizer_subtotal = Phase::_t_iterGVN.seconds() + |
108 Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() + |
110 Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() + |
109 Phase::_t_graphReshaping.seconds(); |
111 Phase::_t_graphReshaping.seconds(); |
110 double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0)); |
112 double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0)); |
111 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", optimizer_subtotal, percent_of_optimizer); |
113 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", optimizer_subtotal, percent_of_optimizer); |
112 } |
114 } |
113 tty->print_cr (" matcher : %3.3f sec", Phase::_t_matcher.seconds()); |
115 tty->print_cr (" matcher : %3.3f sec", Phase::_t_matcher.seconds()); |
114 tty->print_cr (" scheduler : %3.3f sec", Phase::_t_scheduler.seconds()); |
116 tty->print_cr (" scheduler : %3.3f sec", Phase::_t_scheduler.seconds()); |
115 tty->print_cr (" regalloc : %3.3f sec", Phase::_t_registerAllocation.seconds()); |
117 tty->print_cr (" regalloc : %3.3f sec", Phase::_t_registerAllocation.seconds()); |
116 if( Verbose || WizardMode ) { |
118 if( Verbose || WizardMode ) { |
117 tty->print_cr (" ctorChaitin : %3.3f sec", Phase::_t_ctorChaitin.seconds()); |
119 tty->print_cr (" ctorChaitin : %3.3f sec", Phase::_t_ctorChaitin.seconds()); |
118 tty->print_cr (" buildIFG : %3.3f sec", Phase::_t_buildIFGphysical.seconds()); |
120 tty->print_cr (" buildIFG : %3.3f sec", Phase::_t_buildIFGphysical.seconds()); |
119 tty->print_cr (" computeLive : %3.3f sec", Phase::_t_computeLive.seconds()); |
121 tty->print_cr (" computeLive : %3.3f sec", Phase::_t_computeLive.seconds()); |
120 tty->print_cr (" regAllocSplit: %3.3f sec", Phase::_t_regAllocSplit.seconds()); |
122 tty->print_cr (" regAllocSplit : %3.3f sec", Phase::_t_regAllocSplit.seconds()); |
121 tty->print_cr (" postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds()); |
123 tty->print_cr (" postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds()); |
122 tty->print_cr (" fixupSpills : %3.3f sec", Phase::_t_fixupSpills.seconds()); |
124 tty->print_cr (" fixupSpills : %3.3f sec", Phase::_t_fixupSpills.seconds()); |
123 double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() + |
125 double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() + |
124 Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() + |
126 Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() + |
125 Phase::_t_regAllocSplit.seconds() + Phase::_t_fixupSpills.seconds() + |
127 Phase::_t_regAllocSplit.seconds() + Phase::_t_fixupSpills.seconds() + |
126 Phase::_t_postAllocCopyRemoval.seconds(); |
128 Phase::_t_postAllocCopyRemoval.seconds(); |
127 double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0)); |
129 double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0)); |
128 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", regalloc_subtotal, percent_of_regalloc); |
130 tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", regalloc_subtotal, percent_of_regalloc); |
129 } |
131 } |
130 tty->print_cr (" macroExpand : %3.3f sec", Phase::_t_macroExpand.seconds()); |
132 tty->print_cr (" macroExpand : %3.3f sec", Phase::_t_macroExpand.seconds()); |
131 tty->print_cr (" blockOrdering: %3.3f sec", Phase::_t_blockOrdering.seconds()); |
133 tty->print_cr (" blockOrdering : %3.3f sec", Phase::_t_blockOrdering.seconds()); |
132 tty->print_cr (" peephole : %3.3f sec", Phase::_t_peephole.seconds()); |
134 tty->print_cr (" peephole : %3.3f sec", Phase::_t_peephole.seconds()); |
133 tty->print_cr (" codeGen : %3.3f sec", Phase::_t_codeGeneration.seconds()); |
135 tty->print_cr (" codeGen : %3.3f sec", Phase::_t_codeGeneration.seconds()); |
134 tty->print_cr (" install_code : %3.3f sec", Phase::_t_registerMethod.seconds()); |
136 tty->print_cr (" install_code : %3.3f sec", Phase::_t_registerMethod.seconds()); |
135 tty->print_cr (" ------------ : ----------"); |
137 tty->print_cr (" -------------- : ----------"); |
136 double phase_subtotal = Phase::_t_parser.seconds() + |
138 double phase_subtotal = Phase::_t_parser.seconds() + |
137 (DoEscapeAnalysis ? Phase::_t_escapeAnalysis.seconds() : 0.0) + |
139 (DoEscapeAnalysis ? Phase::_t_escapeAnalysis.seconds() : 0.0) + |
138 Phase::_t_optimizer.seconds() + Phase::_t_graphReshaping.seconds() + |
140 Phase::_t_optimizer.seconds() + Phase::_t_graphReshaping.seconds() + |
139 Phase::_t_matcher.seconds() + Phase::_t_scheduler.seconds() + |
141 Phase::_t_matcher.seconds() + Phase::_t_scheduler.seconds() + |
140 Phase::_t_registerAllocation.seconds() + Phase::_t_blockOrdering.seconds() + |
142 Phase::_t_registerAllocation.seconds() + Phase::_t_blockOrdering.seconds() + |
141 Phase::_t_macroExpand.seconds() + Phase::_t_peephole.seconds() + |
143 Phase::_t_macroExpand.seconds() + Phase::_t_peephole.seconds() + |
142 Phase::_t_codeGeneration.seconds() + Phase::_t_registerMethod.seconds(); |
144 Phase::_t_codeGeneration.seconds() + Phase::_t_registerMethod.seconds(); |
143 double percent_of_method_compile = ((phase_subtotal == 0.0) ? 0.0 : phase_subtotal / Phase::_t_methodCompilation.seconds()) * 100.0; |
145 double percent_of_method_compile = ((phase_subtotal == 0.0) ? 0.0 : phase_subtotal / Phase::_t_methodCompilation.seconds()) * 100.0; |
144 // counters inside Compile::CodeGen include time for adapters and stubs |
146 // counters inside Compile::CodeGen include time for adapters and stubs |
145 // so phase-total can be greater than 100% |
147 // so phase-total can be greater than 100% |
146 tty->print_cr (" total : %3.3f sec, %3.2f %%", phase_subtotal, percent_of_method_compile); |
148 tty->print_cr (" total : %3.3f sec, %3.2f %%", phase_subtotal, percent_of_method_compile); |
147 |
149 |
148 assert( percent_of_method_compile > expected_method_compile_coverage || |
150 assert( percent_of_method_compile > expected_method_compile_coverage || |
149 phase_subtotal < minimum_meaningful_method_compile, |
151 phase_subtotal < minimum_meaningful_method_compile, |
150 "Must account for method compilation"); |
152 "Must account for method compilation"); |
151 |
153 |