phase.cpp revision 605
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * Copyright 1997-2008 Sun Microsystems, Inc. All Rights Reserved.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * This code is free software; you can redistribute it and/or modify it
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * under the terms of the GNU General Public License version 2 only, as
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * published by the Free Software Foundation.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * This code is distributed in the hope that it will be useful, but WITHOUT
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * version 2 for more details (a copy is included in the LICENSE file that
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * accompanied this code).
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * You should have received a copy of the GNU General Public License version
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * 2 along with this work; if not, write to the Free Software Foundation,
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * Please contact Sun Microsystems, Inc., 4150 Network Circle, Santa Clara,
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * CA 95054 USA or visit www.sun.com if you need additional information or
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk * have any questions.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk#include "incls/_precompiled.incl"
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk#include "incls/_phase.cpp.incl"
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk// The next timers used for LogCompilation
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk// Subtimers for _t_optimizer
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk// Subtimers for _t_registerAllocation
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk// Subtimers for _t_output
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk//------------------------------Phase------------------------------------------
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenkPhase::Phase( PhaseNumber pnum ) : _pnum(pnum), C( pnum == Compiler ? NULL : Compile::current()) {
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk // Poll for requests from shutdown mechanism to quiesce compiler (4448539, 4448544).
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk // This is an effective place to poll, since the compiler is full of phases.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk // In particular, every inlining site uses a recursively created Parse phase.
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenkstatic const double minimum_reported_time = 0.0001; // seconds
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenkstatic const double expected_method_compile_coverage = 0.97; // %
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenkstatic const double minimum_meaningful_method_compile = 2.00; // seconds
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" Total compilation: %3.3f sec.", Phase::_t_totalCompilation.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print (" method compilation : %3.3f sec", Phase::_t_methodCompilation.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" (%3.0f bytes per sec) ", Phase::_total_bytes_compiled / Phase::_t_methodCompilation.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" stub compilation : %3.3f sec.", Phase::_t_stubCompilation.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" parse : %3.3f sec", Phase::_t_parser.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" escape analysis : %3.3f sec", Phase::_t_escapeAnalysis.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" optimizer : %3.3f sec", Phase::_t_optimizer.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" iterGVN : %3.3f sec", Phase::_t_iterGVN.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" idealLoop : %3.3f sec", Phase::_t_idealLoop.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" ccp : %3.3f sec", Phase::_t_ccp.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" iterGVN2 : %3.3f sec", Phase::_t_iterGVN2.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" graphReshape : %3.3f sec", Phase::_t_graphReshaping.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double optimizer_subtotal = Phase::_t_iterGVN.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_idealLoop.seconds() + Phase::_t_ccp.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double percent_of_optimizer = ((optimizer_subtotal == 0.0) ? 0.0 : (optimizer_subtotal / Phase::_t_optimizer.seconds() * 100.0));
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", optimizer_subtotal, percent_of_optimizer);
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" matcher : %3.3f sec", Phase::_t_matcher.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" scheduler : %3.3f sec", Phase::_t_scheduler.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" regalloc : %3.3f sec", Phase::_t_registerAllocation.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" ctorChaitin : %3.3f sec", Phase::_t_ctorChaitin.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" buildIFG : %3.3f sec", Phase::_t_buildIFGphysical.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" computeLive : %3.3f sec", Phase::_t_computeLive.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" regAllocSplit: %3.3f sec", Phase::_t_regAllocSplit.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" postAllocCopyRemoval: %3.3f sec", Phase::_t_postAllocCopyRemoval.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" fixupSpills : %3.3f sec", Phase::_t_fixupSpills.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double regalloc_subtotal = Phase::_t_ctorChaitin.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_buildIFGphysical.seconds() + Phase::_t_computeLive.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_regAllocSplit.seconds() + Phase::_t_fixupSpills.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double percent_of_regalloc = ((regalloc_subtotal == 0.0) ? 0.0 : (regalloc_subtotal / Phase::_t_registerAllocation.seconds() * 100.0));
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" subtotal : %3.3f sec, %3.2f %%", regalloc_subtotal, percent_of_regalloc);
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" macroExpand : %3.3f sec", Phase::_t_macroExpand.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" blockOrdering: %3.3f sec", Phase::_t_blockOrdering.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" peephole : %3.3f sec", Phase::_t_peephole.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" codeGen : %3.3f sec", Phase::_t_codeGeneration.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" install_code : %3.3f sec", Phase::_t_registerMethod.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double phase_subtotal = Phase::_t_parser.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk (DoEscapeAnalysis ? Phase::_t_escapeAnalysis.seconds() : 0.0) +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_optimizer.seconds() + Phase::_t_graphReshaping.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_matcher.seconds() + Phase::_t_scheduler.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_registerAllocation.seconds() + Phase::_t_blockOrdering.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_macroExpand.seconds() + Phase::_t_peephole.seconds() +
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk Phase::_t_codeGeneration.seconds() + Phase::_t_registerMethod.seconds();
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk double percent_of_method_compile = ((phase_subtotal == 0.0) ? 0.0 : phase_subtotal / Phase::_t_methodCompilation.seconds()) * 100.0;
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk // counters inside Compile::CodeGen include time for adapters and stubs
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk // so phase-total can be greater than 100%
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" total : %3.3f sec, %3.2f %%", phase_subtotal, percent_of_method_compile);
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk assert( percent_of_method_compile > expected_method_compile_coverage ||
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk phase_subtotal < minimum_meaningful_method_compile,
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk "Must account for method compilation");
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk if( Phase::_t_temporaryTimer1.seconds() > minimum_reported_time ) {
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" temporaryTimer1: %3.3f sec", Phase::_t_temporaryTimer1.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk if( Phase::_t_temporaryTimer2.seconds() > minimum_reported_time ) {
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" temporaryTimer2: %3.3f sec", Phase::_t_temporaryTimer2.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" output : %3.3f sec", Phase::_t_output.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" isched : %3.3f sec", Phase::_t_instrSched.seconds());
4b8d88eb610aa1e0bb6ec632f792744b3d6b5f22jeff.schenk tty->print_cr (" bldOopMaps: %3.3f sec", Phase::_t_buildOopMaps.seconds());