src/share/vm/opto/phase.cpp

changeset 1356
046932b72aa2
parent 1040
98cb887364d3
child 1907
c18cbe5936b8
equal deleted inserted replaced
1345:10d8c0d0d60e 1356:046932b72aa2
1 /* 1 /*
2 * Copyright 1997-2008 Sun Microsystems, Inc. All Rights Reserved. 2 * Copyright 1997-2009 Sun Microsystems, Inc. All Rights Reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 * 4 *
5 * This code is free software; you can redistribute it and/or modify it 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 6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation. 7 * published by the Free Software Foundation.
51 elapsedTimer Phase::_t_peephole; 51 elapsedTimer Phase::_t_peephole;
52 elapsedTimer Phase::_t_codeGeneration; 52 elapsedTimer Phase::_t_codeGeneration;
53 elapsedTimer Phase::_t_registerMethod; 53 elapsedTimer Phase::_t_registerMethod;
54 elapsedTimer Phase::_t_temporaryTimer1; 54 elapsedTimer Phase::_t_temporaryTimer1;
55 elapsedTimer Phase::_t_temporaryTimer2; 55 elapsedTimer Phase::_t_temporaryTimer2;
56 elapsedTimer Phase::_t_idealLoopVerify;
56 57
57 // Subtimers for _t_optimizer 58 // Subtimers for _t_optimizer
58 elapsedTimer Phase::_t_iterGVN; 59 elapsedTimer Phase::_t_iterGVN;
59 elapsedTimer Phase::_t_iterGVN2; 60 elapsedTimer Phase::_t_iterGVN2;
60 61
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
155 } 157 }
156 if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) { 158 if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) {
157 tty->cr(); 159 tty->cr();
158 tty->print_cr (" temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds()); 160 tty->print_cr (" temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds());
159 } 161 }
160 tty->print_cr (" output : %3.3f sec", Phase::_t_output.seconds()); 162 tty->print_cr (" output : %3.3f sec", Phase::_t_output.seconds());
161 tty->print_cr (" isched : %3.3f sec", Phase::_t_instrSched.seconds()); 163 tty->print_cr (" isched : %3.3f sec", Phase::_t_instrSched.seconds());
162 tty->print_cr (" bldOopMaps: %3.3f sec", Phase::_t_buildOopMaps.seconds()); 164 tty->print_cr (" bldOopMaps : %3.3f sec", Phase::_t_buildOopMaps.seconds());
163 } 165 }
164 #endif 166 #endif

mercurial