phase.cpp revision 6010:abec000618bf 
1/*
2 * Copyright (c) 1997, 2013, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
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
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25#include "precompiled.hpp"
26#include "code/nmethod.hpp"
27#include "compiler/compileBroker.hpp"
28#include "opto/compile.hpp"
29#include "opto/matcher.hpp"
30#include "opto/node.hpp"
31#include "opto/phase.hpp"
32
33#ifndef PRODUCT
34int Phase::_total_bytes_compiled = 0;
35
36elapsedTimer Phase::_t_totalCompilation;
37elapsedTimer Phase::_t_methodCompilation;
38elapsedTimer Phase::_t_stubCompilation;
39#endif
40
41// The next timers used for LogCompilation
42elapsedTimer Phase::_t_parser;
43elapsedTimer Phase::_t_optimizer;
44elapsedTimer   Phase::_t_escapeAnalysis;
45elapsedTimer     Phase::_t_connectionGraph;
46elapsedTimer   Phase::_t_idealLoop;
47elapsedTimer   Phase::_t_ccp;
48elapsedTimer Phase::_t_matcher;
49elapsedTimer Phase::_t_registerAllocation;
50elapsedTimer Phase::_t_output;
51
52#ifndef PRODUCT
53elapsedTimer Phase::_t_graphReshaping;
54elapsedTimer Phase::_t_scheduler;
55elapsedTimer Phase::_t_blockOrdering;
56elapsedTimer Phase::_t_macroEliminate;
57elapsedTimer Phase::_t_macroExpand;
58elapsedTimer Phase::_t_peephole;
59elapsedTimer Phase::_t_postalloc_expand;
60elapsedTimer Phase::_t_codeGeneration;
61elapsedTimer Phase::_t_registerMethod;
62elapsedTimer Phase::_t_temporaryTimer1;
63elapsedTimer Phase::_t_temporaryTimer2;
64elapsedTimer Phase::_t_idealLoopVerify;
65
66// Subtimers for _t_optimizer
67elapsedTimer   Phase::_t_iterGVN;
68elapsedTimer   Phase::_t_iterGVN2;
69elapsedTimer   Phase::_t_incrInline;
70
71// Subtimers for _t_registerAllocation
72elapsedTimer   Phase::_t_ctorChaitin;
73elapsedTimer   Phase::_t_buildIFGphysical;
74elapsedTimer   Phase::_t_computeLive;
75elapsedTimer   Phase::_t_regAllocSplit;
76elapsedTimer   Phase::_t_postAllocCopyRemoval;
77elapsedTimer   Phase::_t_fixupSpills;
78
79// Subtimers for _t_output
80elapsedTimer   Phase::_t_instrSched;
81elapsedTimer   Phase::_t_buildOopMaps;
82#endif
83
84//------------------------------Phase------------------------------------------
85Phase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) {
86  // 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.
88  // In particular, every inlining site uses a recursively created Parse phase.
89  CompileBroker::maybe_block();
90}
91
92#ifndef PRODUCT
93static const double minimum_reported_time             = 0.0001; // seconds
94static const double expected_method_compile_coverage  = 0.97;   // %
95static const double minimum_meaningful_method_compile = 2.00;   // seconds
96
97void Phase::print_timers() {
98  tty->print_cr ("Accumulated compiler times:");
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) {
110      // EA is part of Optimizer.
111      tty->print_cr ("      escape analysis: %3.3f sec", Phase::_t_escapeAnalysis.seconds());
112      tty->print_cr ("        connection graph: %3.3f sec", Phase::_t_connectionGraph.seconds());
113      tty->print_cr ("      macroEliminate : %3.3f sec", Phase::_t_macroEliminate.seconds());
114    }
115    tty->print_cr ("      iterGVN        : %3.3f sec", Phase::_t_iterGVN.seconds());
116    tty->print_cr ("      incrInline     : %3.3f sec", Phase::_t_incrInline.seconds());
117    tty->print_cr ("      idealLoop      : %3.3f sec", Phase::_t_idealLoop.seconds());
118    tty->print_cr ("      idealLoopVerify: %3.3f sec", Phase::_t_idealLoopVerify.seconds());
119    tty->print_cr ("      ccp            : %3.3f sec", Phase::_t_ccp.seconds());
120    tty->print_cr ("      iterGVN2       : %3.3f sec", Phase::_t_iterGVN2.seconds());
121    tty->print_cr ("      macroExpand    : %3.3f sec", Phase::_t_macroExpand.seconds());
122    tty->print_cr ("      graphReshape   : %3.3f sec", Phase::_t_graphReshaping.seconds());
123    double optimizer_subtotal = Phase::_t_iterGVN.seconds() + Phase::_t_iterGVN2.seconds() +
124      Phase::_t_escapeAnalysis.seconds() + Phase::_t_macroEliminate.seconds() +
125      Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() +
126      Phase::_t_macroExpand.seconds() + Phase::_t_graphReshaping.seconds();
127    double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0));
128    tty->print_cr ("      subtotal       : %3.3f sec,  %3.2f %%", optimizer_subtotal, percent_of_optimizer);
129  }
130  tty->print_cr ("    matcher        : %3.3f sec", Phase::_t_matcher.seconds());
131  tty->print_cr ("    scheduler      : %3.3f sec", Phase::_t_scheduler.seconds());
132  tty->print_cr ("    regalloc       : %3.3f sec", Phase::_t_registerAllocation.seconds());
133  if( Verbose || WizardMode ) {
134    tty->print_cr ("      ctorChaitin    : %3.3f sec", Phase::_t_ctorChaitin.seconds());
135    tty->print_cr ("      buildIFG       : %3.3f sec", Phase::_t_buildIFGphysical.seconds());
136    tty->print_cr ("      computeLive    : %3.3f sec", Phase::_t_computeLive.seconds());
137    tty->print_cr ("      regAllocSplit  : %3.3f sec", Phase::_t_regAllocSplit.seconds());
138    tty->print_cr ("      postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds());
139    tty->print_cr ("      fixupSpills    : %3.3f sec", Phase::_t_fixupSpills.seconds());
140    double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() +
141      Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() +
142      Phase::_t_regAllocSplit.seconds()    + Phase::_t_fixupSpills.seconds() +
143      Phase::_t_postAllocCopyRemoval.seconds();
144    double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0));
145    tty->print_cr ("      subtotal       : %3.3f sec,  %3.2f %%", regalloc_subtotal, percent_of_regalloc);
146  }
147  tty->print_cr ("    blockOrdering  : %3.3f sec", Phase::_t_blockOrdering.seconds());
148  tty->print_cr ("    peephole       : %3.3f sec", Phase::_t_peephole.seconds());
149  if (Matcher::require_postalloc_expand) {
150    tty->print_cr ("    postalloc_expand: %3.3f sec", Phase::_t_postalloc_expand.seconds());
151  }
152  tty->print_cr ("    codeGen        : %3.3f sec", Phase::_t_codeGeneration.seconds());
153  tty->print_cr ("    install_code   : %3.3f sec", Phase::_t_registerMethod.seconds());
154  tty->print_cr ("    -------------- : ----------");
155  double phase_subtotal = Phase::_t_parser.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
165  assert( percent_of_method_compile > expected_method_compile_coverage ||
166          phase_subtotal < minimum_meaningful_method_compile,
167          "Must account for method compilation");
168
169  if( Phase::_t_temporaryTimer1.seconds() > minimum_reported_time ) {
170    tty->cr();
171    tty->print_cr ("    temporaryTimer1: %3.3f sec", Phase::_t_temporaryTimer1.seconds());
172  }
173  if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) {
174    tty->cr();
175    tty->print_cr ("    temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds());
176  }
177  tty->print_cr ("    output         : %3.3f sec", Phase::_t_output.seconds());
178  tty->print_cr ("      isched         : %3.3f sec", Phase::_t_instrSched.seconds());
179  tty->print_cr ("      bldOopMaps     : %3.3f sec", Phase::_t_buildOopMaps.seconds());
180}
181#endif
182