Subzero: Rewrite the pass timing infrastructure. This makes it much more useful for individual analysis and long-term translation performance tracking. 1. Collect and report aggregated across the entire translation, instead of function-by-function. If you really care about a single function, just extract it and translate it separately for analysis. 2. Remove "-verbose time" and just use -timing. 3. Collects two kinds of timings: cumulative and flat. Cumulative measures the total time, even if a callee also times itself. Flat only measures the currently active timer at the top of the stack. The flat times should add up to 100%, but cumulative will usually add up to much more than 100%. BUG= none R=jvoung@chromium.org Review URL: https://codereview.chromium.org/610813002
diff --git a/src/IceCfg.cpp b/src/IceCfg.cpp index 8f51f43..d2c83ab 100644 --- a/src/IceCfg.cpp +++ b/src/IceCfg.cpp
@@ -69,14 +69,14 @@ void Cfg::translate() { if (hasError()) return; + static TimerIdT IDtranslate = GlobalContext::getTimerID("translate"); + TimerMarker T(IDtranslate, getContext()); dump("Initial CFG"); - Timer T_translate; // The set of translation passes and their order are determined by // the target. getTarget()->translate(); - T_translate.printElapsedUs(getContext(), "translate()"); dump("Final output"); } @@ -88,6 +88,9 @@ } void Cfg::renumberInstructions() { + static TimerIdT IDrenumberInstructions = + GlobalContext::getTimerID("renumberInstructions"); + TimerMarker T(IDrenumberInstructions, getContext()); NextInstNumber = 1; for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->renumberInstructions(); @@ -96,6 +99,8 @@ // placePhiLoads() must be called before placePhiStores(). void Cfg::placePhiLoads() { + static TimerIdT IDplacePhiLoads = GlobalContext::getTimerID("placePhiLoads"); + TimerMarker T(IDplacePhiLoads, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->placePhiLoads(); } @@ -103,34 +108,48 @@ // placePhiStores() must be called after placePhiLoads(). void Cfg::placePhiStores() { + static TimerIdT IDplacePhiStores = + GlobalContext::getTimerID("placePhiStores"); + TimerMarker T(IDplacePhiStores, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->placePhiStores(); } } void Cfg::deletePhis() { + static TimerIdT IDdeletePhis = GlobalContext::getTimerID("deletePhis"); + TimerMarker T(IDdeletePhis, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->deletePhis(); } } void Cfg::doArgLowering() { + static TimerIdT IDdoArgLowering = GlobalContext::getTimerID("doArgLowering"); + TimerMarker T(IDdoArgLowering, getContext()); getTarget()->lowerArguments(); } void Cfg::doAddressOpt() { + static TimerIdT IDdoAddressOpt = GlobalContext::getTimerID("doAddressOpt"); + TimerMarker T(IDdoAddressOpt, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->doAddressOpt(); } } void Cfg::doNopInsertion() { + static TimerIdT IDdoNopInsertion = + GlobalContext::getTimerID("doNopInsertion"); + TimerMarker T(IDdoNopInsertion, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->doNopInsertion(); } } void Cfg::genCode() { + static TimerIdT IDgenCode = GlobalContext::getTimerID("genCode"); + TimerMarker T(IDgenCode, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->genCode(); } @@ -138,6 +157,8 @@ // Compute the stack frame layout. void Cfg::genFrame() { + static TimerIdT IDgenFrame = GlobalContext::getTimerID("genFrame"); + TimerMarker T(IDgenFrame, getContext()); getTarget()->addProlog(Entry); // TODO: Consider folding epilog generation into the final // emission/assembly pass to avoid an extra iteration over the node @@ -154,6 +175,9 @@ // completely with a single block. It is a quick single pass and // doesn't need to iterate until convergence. void Cfg::livenessLightweight() { + static TimerIdT IDlivenessLightweight = + GlobalContext::getTimerID("livenessLightweight"); + TimerMarker T(IDlivenessLightweight, getContext()); getVMetadata()->init(); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->livenessLightweight(); @@ -161,6 +185,8 @@ } void Cfg::liveness(LivenessMode Mode) { + static TimerIdT IDliveness = GlobalContext::getTimerID("liveness"); + TimerMarker T(IDliveness, getContext()); Live.reset(new Liveness(this, Mode)); getVMetadata()->init(); Live->init(); @@ -199,9 +225,10 @@ // Collect timing for just the portion that constructs the live // range intervals based on the end-of-live-range computation, for a // finer breakdown of the cost. - Timer T_liveRange; // Make a final pass over instructions to delete dead instructions // and build each Variable's live range. + static TimerIdT IDliveRange = GlobalContext::getTimerID("liveRange"); + TimerMarker T1(IDliveRange, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { (*I)->livenessPostprocess(Mode, getLiveness()); } @@ -241,7 +268,6 @@ if (Var->getWeight().isInf()) Var->setLiveRangeInfiniteWeight(); } - T_liveRange.printElapsedUs(getContext(), "live range construction"); dump(); } } @@ -249,6 +275,9 @@ // Traverse every Variable of every Inst and verify that it // appears within the Variable's computed live range. bool Cfg::validateLiveness() const { + static TimerIdT IDvalidateLiveness = + GlobalContext::getTimerID("validateLiveness"); + TimerMarker T(IDvalidateLiveness, getContext()); bool Valid = true; Ostream &Str = Ctx->getStrDump(); for (NodeList::const_iterator I1 = Nodes.begin(), E1 = Nodes.end(); I1 != E1; @@ -296,18 +325,21 @@ } void Cfg::doBranchOpt() { + static TimerIdT IDdoBranchOpt = GlobalContext::getTimerID("doBranchOpt"); + TimerMarker T(IDdoBranchOpt, getContext()); for (NodeList::iterator I = Nodes.begin(), E = Nodes.end(); I != E; ++I) { NodeList::iterator NextNode = I; ++NextNode; - (*I)->doBranchOpt(*NextNode); + (*I)->doBranchOpt(NextNode == E ? NULL : *NextNode); } } // ======================== Dump routines ======================== // void Cfg::emit() { + static TimerIdT IDemit = GlobalContext::getTimerID("emit"); + TimerMarker T(IDemit, getContext()); Ostream &Str = Ctx->getStrEmit(); - Timer T_emit; if (!Ctx->testAndSetHasEmittedFirstMethod()) { // Print a helpful command for assembling the output. // TODO: have the Target emit the header @@ -339,7 +371,6 @@ (*I)->emit(this); } Str << "\n"; - T_emit.printElapsedUs(Ctx, "emit()"); } // Dumps the IR with an optional introductory message.
diff --git a/src/IceConverter.cpp b/src/IceConverter.cpp index 4888e8f..9910f06 100644 --- a/src/IceConverter.cpp +++ b/src/IceConverter.cpp
@@ -11,11 +11,10 @@ // //===----------------------------------------------------------------------===// -#include "IceConverter.h" - #include "IceCfg.h" #include "IceCfgNode.h" #include "IceClFlags.h" +#include "IceConverter.h" #include "IceDefs.h" #include "IceGlobalContext.h" #include "IceInst.h" @@ -60,6 +59,9 @@ // Caller is expected to delete the returned Ice::Cfg object. Ice::Cfg *convertFunction(const Function *F) { + static Ice::TimerIdT IDllvmConvert = + Ice::GlobalContext::getTimerID("llvmConvert"); + Ice::TimerMarker T(IDllvmConvert, Ctx); VarMap.clear(); NodeMap.clear(); Func = new Ice::Cfg(Ctx); @@ -621,6 +623,8 @@ namespace Ice { void Converter::convertToIce() { + static TimerIdT IDconvertToIce = GlobalContext::getTimerID("convertToIce"); + TimerMarker T(IDconvertToIce, Ctx); nameUnnamedGlobalAddresses(Mod); if (!Ctx->getFlags().DisableGlobals) convertGlobals(Mod); @@ -635,11 +639,6 @@ Timer TConvert; Cfg *Fcn = FunctionConverter.convertFunction(I); - if (Ctx->getFlags().SubzeroTimingEnabled) { - std::cerr << "[Subzero timing] Convert function " - << Fcn->getFunctionName() << ": " << TConvert.getElapsedSec() - << " sec\n"; - } translateFcn(Fcn); }
diff --git a/src/IceDefs.h b/src/IceDefs.h index 4aa99e2..68f30c7 100644 --- a/src/IceDefs.h +++ b/src/IceDefs.h
@@ -78,6 +78,8 @@ // numbers are used for representing Variable live ranges. typedef int32_t InstNumberT; +typedef uint32_t TimerIdT; + enum LivenessMode { // Basic version of live-range-end calculation. Marks the last uses // of variables based on dataflow analysis. Records the set of @@ -103,34 +105,14 @@ IceV_RegOrigins = 1 << 7, IceV_LinearScan = 1 << 8, IceV_Frame = 1 << 9, - IceV_Timing = 1 << 10, - IceV_AddrOpt = 1 << 11, + IceV_AddrOpt = 1 << 10, IceV_All = ~IceV_None, - IceV_Most = IceV_All & ~(IceV_Timing | IceV_LinearScan) + IceV_Most = IceV_All & ~IceV_LinearScan }; typedef uint32_t VerboseMask; typedef llvm::raw_ostream Ostream; -// TODO: Implement in terms of std::chrono after switching to C++11. -class Timer { -public: - Timer() : Start(llvm::TimeRecord::getCurrentTime(false)) {} - uint64_t getElapsedNs() const { return getElapsedSec() * 1000 * 1000 * 1000; } - uint64_t getElapsedUs() const { return getElapsedSec() * 1000 * 1000; } - uint64_t getElapsedMs() const { return getElapsedSec() * 1000; } - double getElapsedSec() const { - llvm::TimeRecord End = llvm::TimeRecord::getCurrentTime(false); - return End.getWallTime() - Start.getWallTime(); - } - void printElapsedUs(GlobalContext *Ctx, const IceString &Tag) const; - -private: - const llvm::TimeRecord Start; - Timer(const Timer &) LLVM_DELETED_FUNCTION; - Timer &operator=(const Timer &) LLVM_DELETED_FUNCTION; -}; - } // end of namespace Ice #endif // SUBZERO_SRC_ICEDEFS_H
diff --git a/src/IceGlobalContext.cpp b/src/IceGlobalContext.cpp index 319e18a..4cca6c9 100644 --- a/src/IceGlobalContext.cpp +++ b/src/IceGlobalContext.cpp
@@ -1,4 +1,4 @@ -//===- subzero/src/IceGlobalContext.cpp - Global context defs ---*- C++ -*-===// +//===- subzero/src/IceGlobalContext.cpp - Global context defs -------------===// // // The Subzero Code Generator // @@ -22,6 +22,7 @@ #include "IceGlobalContext.h" #include "IceOperand.h" #include "IceTargetLowering.h" +#include "IceTimerTree.h" namespace Ice { @@ -122,7 +123,7 @@ : StrDump(OsDump), StrEmit(OsEmit), VMask(Mask), ConstPool(new ConstantPool()), Arch(Arch), Opt(Opt), TestPrefix(TestPrefix), Flags(Flags), HasEmittedFirstMethod(false), - RNG("") {} + RNG(""), Timers(new TimerStack("main")) {} // Scan a string for S[0-9A-Z]*_ patterns and replace them with // S<num>_ where <num> is the next base-36 value. If a type name @@ -384,6 +385,14 @@ llvm_unreachable("Unknown type"); } +TimerIdT GlobalContext::getTimerID(const IceString &Name) { + return TimerStack::getTimerID(Name); +} + +void GlobalContext::pushTimer(TimerIdT ID) { Timers->push(ID); } + +void GlobalContext::popTimer(TimerIdT ID) { Timers->pop(ID); } + void GlobalContext::dumpStats(const IceString &Name, bool Final) { if (Flags.DumpStats) { if (Final) { @@ -395,12 +404,6 @@ } } -void Timer::printElapsedUs(GlobalContext *Ctx, const IceString &Tag) const { - if (Ctx->isVerbose(IceV_Timing)) { - // Prefixing with '#' allows timing strings to be included - // without error in textual assembly output. - Ctx->getStrDump() << "# " << getElapsedUs() << " usec " << Tag << "\n"; - } -} +void GlobalContext::dumpTimers() { Timers->dump(getStrDump()); } } // end of namespace Ice
diff --git a/src/IceGlobalContext.h b/src/IceGlobalContext.h index f997b65..3c53773 100644 --- a/src/IceGlobalContext.h +++ b/src/IceGlobalContext.h
@@ -69,12 +69,8 @@ // Returns true if any of the specified options in the verbose mask // are set. If the argument is omitted, it checks if any verbose - // options at all are set. IceV_Timing is treated specially, so - // that running with just IceV_Timing verbosity doesn't trigger an - // avalanche of extra output. - bool isVerbose(VerboseMask Mask = (IceV_All & ~IceV_Timing)) const { - return VMask & Mask; - } + // options at all are set. + bool isVerbose(VerboseMask Mask = IceV_All) const { return VMask & Mask; } void setVerbose(VerboseMask Mask) { VMask = Mask; } void addVerbose(VerboseMask Mask) { VMask |= Mask; } void subVerbose(VerboseMask Mask) { VMask &= ~Mask; } @@ -154,6 +150,11 @@ StatsCumulative.updateFills(); } + static TimerIdT getTimerID(const IceString &Name); + void pushTimer(TimerIdT ID); + void popTimer(TimerIdT ID); + void dumpTimers(); + private: Ostream *StrDump; // Stream for dumping / diagnostics Ostream *StrEmit; // Stream for code emission @@ -170,6 +171,7 @@ RandomNumberGenerator RNG; CodeStats StatsFunction; CodeStats StatsCumulative; + llvm::OwningPtr<class TimerStack> Timers; GlobalContext(const GlobalContext &) LLVM_DELETED_FUNCTION; GlobalContext &operator=(const GlobalContext &) LLVM_DELETED_FUNCTION; @@ -178,6 +180,30 @@ void incrementSubstitutions(ManglerVector &OldName) const; }; +// Helper class to push and pop a timer marker. The constructor +// pushes a marker, and the destructor pops it. This is for +// convenient timing of regions of code. +class TimerMarker { + TimerMarker(const TimerMarker &) LLVM_DELETED_FUNCTION; + TimerMarker &operator=(const TimerMarker &) LLVM_DELETED_FUNCTION; + +public: + TimerMarker(TimerIdT ID, GlobalContext *Ctx) + : ID(ID), Ctx(Ctx), Active(Ctx->getFlags().SubzeroTimingEnabled) { + if (Active) + Ctx->pushTimer(ID); + } + ~TimerMarker() { + if (Active) + Ctx->popTimer(ID); + } + +private: + TimerIdT ID; + GlobalContext *const Ctx; + const bool Active; +}; + } // end of namespace Ice #endif // SUBZERO_SRC_ICEGLOBALCONTEXT_H
diff --git a/src/IceInst.h b/src/IceInst.h index 5c50d2f..3727e6e 100644 --- a/src/IceInst.h +++ b/src/IceInst.h
@@ -509,9 +509,9 @@ class InstLoad : public InstHighLevel { public: static InstLoad *create(Cfg *Func, Variable *Dest, Operand *SourceAddr, - uint32_t align = 1) { + uint32_t Align = 1) { // TODO(kschimpf) Stop ignoring alignment specification. - (void)align; + (void)Align; return new (Func->allocateInst<InstLoad>()) InstLoad(Func, Dest, SourceAddr); }
diff --git a/src/IceOperand.cpp b/src/IceOperand.cpp index d1854f4..3614725 100644 --- a/src/IceOperand.cpp +++ b/src/IceOperand.cpp
@@ -122,9 +122,26 @@ } bool LiveRange::overlaps(InstNumberT OtherBegin) const { + bool Result = false; + for (RangeType::const_iterator I = Range.begin(), E = Range.end(); I != E; + ++I) { + if (OtherBegin < I->first) { + Result = false; + break; + } + if (OtherBegin < I->second) { + Result = true; + break; + } + } +#if 0 + // An equivalent but less inefficient implementation: LiveRange Temp; Temp.addSegment(OtherBegin, OtherBegin + 1); - return overlaps(Temp); + bool Validation = overlaps(Temp); + assert(Result == Validation); +#endif + return Result; } // Returns true if the live range contains the given instruction @@ -259,6 +276,8 @@ } void VariablesMetadata::init() { + static TimerIdT IDvmetadata = GlobalContext::getTimerID("vmetadata"); + TimerMarker T(IDvmetadata, Func->getContext()); Metadata.clear(); Metadata.resize(Func->getNumVariables());
diff --git a/src/IceRegAlloc.cpp b/src/IceRegAlloc.cpp index 36ada12..e072085 100644 --- a/src/IceRegAlloc.cpp +++ b/src/IceRegAlloc.cpp
@@ -64,12 +64,15 @@ // preparation. Results are assigned to Variable::RegNum for each // Variable. void LinearScan::scan(const llvm::SmallBitVector &RegMaskFull) { + static TimerIdT IDscan = GlobalContext::getTimerID("linearScan"); + TimerMarker T(IDscan, Func->getContext()); assert(RegMaskFull.any()); // Sanity check Unhandled.clear(); Handled.clear(); Inactive.clear(); Active.clear(); Ostream &Str = Func->getContext()->getStrDump(); + bool Verbose = Func->getContext()->isVerbose(IceV_LinearScan); Func->resetCurrentNode(); VariablesMetadata *VMetadata = Func->getVMetadata(); @@ -81,26 +84,32 @@ // a result, it may be useful to design a better data structure for // storing Func->getVariables(). const VarList &Vars = Func->getVariables(); - for (VarList::const_iterator I = Vars.begin(), E = Vars.end(); I != E; ++I) { - Variable *Var = *I; - // Explicitly don't consider zero-weight variables, which are - // meant to be spill slots. - if (Var->getWeight() == RegWeight::Zero) - continue; - // Don't bother if the variable has a null live range, which means - // it was never referenced. - if (Var->getLiveRange().isEmpty()) - continue; - Unhandled.insert(LiveRangeWrapper(Var)); - if (Var->hasReg()) { - Var->setRegNumTmp(Var->getRegNum()); - Var->setLiveRangeInfiniteWeight(); + { + static TimerIdT IDinitUnhandled = + GlobalContext::getTimerID("initUnhandled"); + TimerMarker T(IDinitUnhandled, Func->getContext()); + for (VarList::const_iterator I = Vars.begin(), E = Vars.end(); I != E; + ++I) { + Variable *Var = *I; + // Explicitly don't consider zero-weight variables, which are + // meant to be spill slots. + if (Var->getWeight() == RegWeight::Zero) + continue; + // Don't bother if the variable has a null live range, which means + // it was never referenced. + if (Var->getLiveRange().isEmpty()) + continue; + Unhandled.insert(LiveRangeWrapper(Var)); + if (Var->hasReg()) { + Var->setRegNumTmp(Var->getRegNum()); + Var->setLiveRangeInfiniteWeight(); + } } } // RegUses[I] is the number of live ranges (variables) that register // I is currently assigned to. It can be greater than 1 as a result - // of Variable::AllowRegisterOverlap. + // of AllowOverlap inference below. std::vector<int> RegUses(RegMaskFull.size()); // Unhandled is already set to all ranges in increasing order of // start points. @@ -112,7 +121,7 @@ while (!Unhandled.empty()) { LiveRangeWrapper Cur = *Unhandled.begin(); Unhandled.erase(Unhandled.begin()); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "\nConsidering "; Cur.dump(Func); Str << "\n"; @@ -130,7 +139,7 @@ int32_t RegNum = Cur.Var->getRegNum(); // RegNumTmp should have already been set above. assert(Cur.Var->getRegNumTmp() == RegNum); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Precoloring "; Cur.dump(Func); Str << "\n"; @@ -150,7 +159,7 @@ bool Moved = false; if (Item.endsBefore(Cur)) { // Move Item from Active to Handled list. - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Expiring "; Item.dump(Func); Str << "\n"; @@ -160,7 +169,7 @@ Moved = true; } else if (!Item.overlapsStart(Cur)) { // Move Item from Active to Inactive list. - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Inactivating "; Item.dump(Func); Str << "\n"; @@ -186,7 +195,7 @@ LiveRangeWrapper Item = *I; if (Item.endsBefore(Cur)) { // Move Item from Inactive to Handled list. - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Expiring "; Item.dump(Func); Str << "\n"; @@ -195,7 +204,7 @@ Handled.push_back(Item); } else if (Item.overlapsStart(Cur)) { // Move Item from Inactive to Active list. - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Reactivating "; Item.dump(Func); Str << "\n"; @@ -261,7 +270,7 @@ } } } - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { if (Prefer) { Str << "Initial Prefer=" << *Prefer << " R=" << PreferReg << " LIVE=" << Prefer->getLiveRange() << " Overlap=" << AllowOverlap @@ -279,8 +288,7 @@ int32_t RegNum = Item.Var->getRegNumTmp(); // Don't assert(Free[RegNum]) because in theory (though // probably never in practice) there could be two inactive - // variables that were allowed marked with - // AllowRegisterOverlap. + // variables that were marked with AllowOverlap. Free[RegNum] = false; // Disable AllowOverlap if an Inactive variable, which is not // Prefer, shares Prefer's register, and has a definition @@ -331,7 +339,7 @@ } // Print info about physical register availability. - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { for (SizeT i = 0; i < RegMask.size(); ++i) { if (RegMask[i]) { Str << Func->getTarget()->getRegName(i, IceType_i32) @@ -346,7 +354,7 @@ // First choice: a preferred register that is either free or is // allowed to overlap with its linked variable. Cur.Var->setRegNumTmp(PreferReg); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Preferring "; Cur.dump(Func); Str << "\n"; @@ -360,7 +368,7 @@ // picking the lowest-numbered available register? int32_t RegNum = Free.find_first(); Cur.Var->setRegNumTmp(RegNum); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Allocating "; Cur.dump(Func); Str << "\n"; @@ -434,7 +442,7 @@ ++Next; LiveRangeWrapper Item = *I; if (Item.Var->getRegNumTmp() == MinWeightIndex) { - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Evicting "; Item.dump(Func); Str << "\n"; @@ -463,7 +471,7 @@ // instructions. if (Item.Var->getRegNumTmp() == MinWeightIndex && Item.overlaps(Cur)) { - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Evicting "; Item.dump(Func); Str << "\n"; @@ -478,7 +486,7 @@ assert(RegUses[MinWeightIndex] >= 0); ++RegUses[MinWeightIndex]; Active.push_back(Cur); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { Str << "Allocating "; Cur.dump(Func); Str << "\n"; @@ -509,7 +517,7 @@ I != E; ++I) { LiveRangeWrapper Item = *I; int32_t RegNum = Item.Var->getRegNumTmp(); - if (Func->getContext()->isVerbose(IceV_LinearScan)) { + if (Verbose) { if (!Item.Var->hasRegTmp()) { Str << "Not assigning "; Item.Var->dump(Func);
diff --git a/src/IceTargetLowering.cpp b/src/IceTargetLowering.cpp index f663155..76d3473 100644 --- a/src/IceTargetLowering.cpp +++ b/src/IceTargetLowering.cpp
@@ -229,6 +229,8 @@ // registers could potentially be parameterized if we want to restrict // registers e.g. for performance testing. void TargetLowering::regAlloc() { + static TimerIdT IDregAlloc = GlobalContext::getTimerID("regAlloc"); + TimerMarker T(IDregAlloc, Ctx); LinearScan LinearScan(Func); RegSetMask RegInclude = RegSet_None; RegSetMask RegExclude = RegSet_None;
diff --git a/src/IceTargetLoweringX8632.cpp b/src/IceTargetLoweringX8632.cpp index 96cc57b..b9d3170 100644 --- a/src/IceTargetLoweringX8632.cpp +++ b/src/IceTargetLoweringX8632.cpp
@@ -302,35 +302,27 @@ void TargetX8632::translateO2() { GlobalContext *Context = Func->getContext(); + static TimerIdT IDO2 = GlobalContext::getTimerID("O2"); + TimerMarker T(IDO2, Context); // Lower Phi instructions. - Timer T_placePhiLoads; Func->placePhiLoads(); if (Func->hasError()) return; - T_placePhiLoads.printElapsedUs(Context, "placePhiLoads()"); - Timer T_placePhiStores; Func->placePhiStores(); if (Func->hasError()) return; - T_placePhiStores.printElapsedUs(Context, "placePhiStores()"); - Timer T_deletePhis; Func->deletePhis(); if (Func->hasError()) return; - T_deletePhis.printElapsedUs(Context, "deletePhis()"); Func->dump("After Phi lowering"); // Address mode optimization. - Timer T_doAddressOpt; Func->getVMetadata()->init(); Func->doAddressOpt(); - T_doAddressOpt.printElapsedUs(Context, "doAddressOpt()"); // Argument lowering - Timer T_argLowering; Func->doArgLowering(); - T_argLowering.printElapsedUs(Context, "lowerArguments()"); // Target lowering. This requires liveness analysis for some parts // of the lowering decisions, such as compare/branch fusing. If @@ -338,40 +330,30 @@ // to be renumbered first. TODO: This renumbering should only be // necessary if we're actually calculating live intervals, which we // only do for register allocation. - Timer T_renumber1; Func->renumberInstructions(); if (Func->hasError()) return; - T_renumber1.printElapsedUs(Context, "renumberInstructions()"); // TODO: It should be sufficient to use the fastest liveness // calculation, i.e. livenessLightweight(). However, for some // reason that slows down the rest of the translation. Investigate. - Timer T_liveness1; Func->liveness(Liveness_Basic); if (Func->hasError()) return; - T_liveness1.printElapsedUs(Context, "liveness()"); Func->dump("After x86 address mode opt"); - Timer T_genCode; Func->genCode(); if (Func->hasError()) return; - T_genCode.printElapsedUs(Context, "genCode()"); // Register allocation. This requires instruction renumbering and // full liveness analysis. - Timer T_renumber2; Func->renumberInstructions(); if (Func->hasError()) return; - T_renumber2.printElapsedUs(Context, "renumberInstructions()"); - Timer T_liveness2; Func->liveness(Liveness_Intervals); if (Func->hasError()) return; - T_liveness2.printElapsedUs(Context, "liveness()"); // Validate the live range computations. Do it outside the timing // code. TODO: Put this under a flag. bool ValidLiveness = Func->validateLiveness(); @@ -381,20 +363,16 @@ // The post-codegen dump is done here, after liveness analysis and // associated cleanup, to make the dump cleaner and more useful. Func->dump("After initial x8632 codegen"); - Timer T_regAlloc; Func->getVMetadata()->init(); regAlloc(); if (Func->hasError()) return; - T_regAlloc.printElapsedUs(Context, "regAlloc()"); Func->dump("After linear scan regalloc"); // Stack frame mapping. - Timer T_genFrame; Func->genFrame(); if (Func->hasError()) return; - T_genFrame.printElapsedUs(Context, "genFrame()"); Func->dump("After stack frame mapping"); // Branch optimization. This needs to be done just before code @@ -413,39 +391,29 @@ void TargetX8632::translateOm1() { GlobalContext *Context = Func->getContext(); - Timer T_placePhiLoads; + static TimerIdT IDOm1 = GlobalContext::getTimerID("Om1"); + TimerMarker T(IDOm1, Context); Func->placePhiLoads(); if (Func->hasError()) return; - T_placePhiLoads.printElapsedUs(Context, "placePhiLoads()"); - Timer T_placePhiStores; Func->placePhiStores(); if (Func->hasError()) return; - T_placePhiStores.printElapsedUs(Context, "placePhiStores()"); - Timer T_deletePhis; Func->deletePhis(); if (Func->hasError()) return; - T_deletePhis.printElapsedUs(Context, "deletePhis()"); Func->dump("After Phi lowering"); - Timer T_argLowering; Func->doArgLowering(); - T_argLowering.printElapsedUs(Context, "lowerArguments()"); - Timer T_genCode; Func->genCode(); if (Func->hasError()) return; - T_genCode.printElapsedUs(Context, "genCode()"); Func->dump("After initial x8632 codegen"); - Timer T_genFrame; Func->genFrame(); if (Func->hasError()) return; - T_genFrame.printElapsedUs(Context, "genFrame()"); Func->dump("After stack frame mapping"); // Nop insertion
diff --git a/src/IceTimerTree.cpp b/src/IceTimerTree.cpp new file mode 100644 index 0000000..4bdb80a --- /dev/null +++ b/src/IceTimerTree.cpp
@@ -0,0 +1,142 @@ +//===- subzero/src/IceTimerTree.cpp - Pass timer defs ---------------------===// +// +// The Subzero Code Generator +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// This file defines the TimerTree class, which tracks flat and +// cumulative execution time collection of call chains. +// +//===----------------------------------------------------------------------===// + +#include "IceDefs.h" +#include "IceTimerTree.h" + +namespace Ice { + +std::vector<IceString> TimerStack::IDs; + +TimerStack::TimerStack(const IceString &TopLevelName) + : FirstTimestamp(timestamp()), LastTimestamp(FirstTimestamp), + StateChangeCount(0), StackTop(0) { + Nodes.resize(1); // Reserve Nodes[0] for the root node. + push(getTimerID(TopLevelName)); +} + +// Returns the unique timer ID for the given Name, creating a new ID +// if needed. For performance reasons, it's best to make only one +// call per Name and cache the result, e.g. via a static initializer. +TimerIdT TimerStack::getTimerID(const IceString &Name) { + TimerIdT Size = IDs.size(); + for (TimerIdT i = 0; i < Size; ++i) { + if (IDs[i] == Name) + return i; + } + IDs.push_back(Name); + return Size; +} + +// Pushes a new marker onto the timer stack. +void TimerStack::push(TimerIdT ID) { + update(); + if (Nodes[StackTop].Children.size() <= ID) + Nodes[StackTop].Children.resize(ID + 1); + if (Nodes[StackTop].Children[ID] == 0) { + TTindex Size = Nodes.size(); + Nodes[StackTop].Children[ID] = Size; + Nodes.resize(Size + 1); + Nodes[Size].Parent = StackTop; + Nodes[Size].Interior = ID; + } + StackTop = Nodes[StackTop].Children[ID]; +} + +// Pop the top marker from the timer stack. Validates via assert() +// that the expected marker is popped. +void TimerStack::pop(TimerIdT ID) { + update(); + assert(StackTop); + assert(Nodes[StackTop].Parent < StackTop); + // Verify that the expected ID is being popped. + assert(Nodes[StackTop].Interior == ID); + (void)ID; + // Verify that the parent's child points to the current stack top. + assert(Nodes[Nodes[StackTop].Parent].Children[ID] == StackTop); + StackTop = Nodes[StackTop].Parent; +} + +// At a state change (e.g. push or pop), updates the flat and +// cumulative timings for everything on the timer stack. +void TimerStack::update() { + ++StateChangeCount; + // Whenever the stack is about to change, we grab the time delta + // since the last change and add it to all active cumulative + // elements and to the flat element for the top of the stack. + double Current = timestamp(); + double Delta = Current - LastTimestamp; + LastTimestamp = Current; + if (StackTop) { + TimerIdT Leaf = Nodes[StackTop].Interior; + if (Leaf >= LeafTimes.size()) + LeafTimes.resize(Leaf + 1); + LeafTimes[Leaf] += Delta; + } + TTindex Prefix = StackTop; + while (Prefix) { + Nodes[Prefix].Time += Delta; + TTindex Next = Nodes[Prefix].Parent; + assert(Next < Prefix); + Prefix = Next; + } +} + +namespace { + +typedef std::multimap<double, IceString> DumpMapType; + +// Dump the Map items in reverse order of their time contribution. +void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime) { + for (DumpMapType::const_reverse_iterator I = Map.rbegin(), E = Map.rend(); + I != E; ++I) { + char buf[80]; + snprintf(buf, llvm::array_lengthof(buf), " %10.6f (%4.1f%%): ", I->first, + I->first * 100 / TotalTime); + Str << buf << I->second << "\n"; + } +} + +} // end of anonymous namespace + +void TimerStack::dump(Ostream &Str) { + update(); + double TotalTime = LastTimestamp - FirstTimestamp; + assert(TotalTime); + Str << "Cumulative function times:\n"; + DumpMapType CumulativeMap; + for (TTindex i = 1; i < Nodes.size(); ++i) { + TTindex Prefix = i; + IceString Suffix = ""; + while (Prefix) { + if (Suffix.empty()) + Suffix = IDs[Nodes[Prefix].Interior]; + else + Suffix = IDs[Nodes[Prefix].Interior] + "." + Suffix; + assert(Nodes[Prefix].Parent < Prefix); + Prefix = Nodes[Prefix].Parent; + } + CumulativeMap.insert(std::make_pair(Nodes[i].Time, Suffix)); + } + dumpHelper(Str, CumulativeMap, TotalTime); + Str << "Flat function times:\n"; + DumpMapType FlatMap; + for (TimerIdT i = 0; i < LeafTimes.size(); ++i) { + FlatMap.insert(std::make_pair(LeafTimes[i], IDs[i])); + } + dumpHelper(Str, FlatMap, TotalTime); + Str << "Number of timer updates: " << StateChangeCount << "\n"; +} + +} // end of namespace Ice
diff --git a/src/IceTimerTree.h b/src/IceTimerTree.h new file mode 100644 index 0000000..3162587 --- /dev/null +++ b/src/IceTimerTree.h
@@ -0,0 +1,68 @@ +//===- subzero/src/IceTimerTree.h - Pass timer defs -------------*- C++ -*-===// +// +// The Subzero Code Generator +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +// This file declares the TimerTree class, which allows flat and +// cumulative execution time collection of call chains. +// +//===----------------------------------------------------------------------===// + +#ifndef SUBZERO_SRC_ICETIMERTREE_H +#define SUBZERO_SRC_ICETIMERTREE_H + +namespace Ice { + +class TimerTreeNode; + +// Timer tree index type +typedef std::vector<TimerTreeNode>::size_type TTindex; + +// TimerTreeNode represents an interior or leaf node in the call tree. +// It contains a list of children, a pointer to its parent, and the +// timer ID for the node. It also holds the cumulative time spent at +// this node and below. The children are always at a higher index in +// the TimerTreeNode::Nodes array, and the parent is always at a lower +// index. +class TimerTreeNode { +public: + TimerTreeNode() : Parent(0), Interior(0), Time(0) {} + std::vector<TTindex> Children; // indexed by TimerIdT + TTindex Parent; + TimerIdT Interior; + double Time; +}; + +class TimerStack { + TimerStack(const TimerStack &) LLVM_DELETED_FUNCTION; + TimerStack &operator=(const TimerStack &) LLVM_DELETED_FUNCTION; + +public: + TimerStack(const IceString &TopLevelName); + static TimerIdT getTimerID(const IceString &Name); + void push(TimerIdT ID); + void pop(TimerIdT ID); + void dump(Ostream &Str); + +private: + void update(); + static double timestamp() { + // TODO: Implement in terms of std::chrono for C++11. + return llvm::TimeRecord::getCurrentTime(false).getWallTime(); + } + const double FirstTimestamp; + double LastTimestamp; + uint64_t StateChangeCount; + static std::vector<IceString> IDs; // indexed by TimerIdT + std::vector<TimerTreeNode> Nodes; // indexed by TTindex + std::vector<double> LeafTimes; // indexed by TimerIdT + TTindex StackTop; +}; + +} // end of namespace Ice + +#endif // SUBZERO_SRC_ICETIMERTREE_H
diff --git a/src/IceTranslator.cpp b/src/IceTranslator.cpp index e0c7e2d..91dcfd4 100644 --- a/src/IceTranslator.cpp +++ b/src/IceTranslator.cpp
@@ -12,12 +12,11 @@ // //===----------------------------------------------------------------------===// -#include "IceTranslator.h" - #include "IceCfg.h" #include "IceClFlags.h" #include "IceDefs.h" #include "IceTargetLowering.h" +#include "IceTranslator.h" #include "llvm/IR/Module.h" #include "llvm/IR/Constant.h" #include "llvm/IR/Constants.h" @@ -80,24 +79,13 @@ if (Ctx->getFlags().DisableTranslation) { Func->dump(); } else { - Timer TTranslate; Func->translate(); - if (Ctx->getFlags().SubzeroTimingEnabled) { - std::cerr << "[Subzero timing] Translate function " - << Func->getFunctionName() << ": " << TTranslate.getElapsedSec() - << " sec\n"; - } if (Func->hasError()) { std::cerr << "ICE translation error: " << Func->getError() << "\n"; ErrorStatus = true; } - Timer TEmit; Func->emit(); - if (Ctx->getFlags().SubzeroTimingEnabled) { - std::cerr << "[Subzero timing] Emit function " << Func->getFunctionName() - << ": " << TEmit.getElapsedSec() << " sec\n"; - } Ctx->dumpStats(Func->getFunctionName()); } }
diff --git a/src/PNaClTranslator.cpp b/src/PNaClTranslator.cpp index 47f6a5e..e1925df 100644 --- a/src/PNaClTranslator.cpp +++ b/src/PNaClTranslator.cpp
@@ -12,7 +12,6 @@ // //===----------------------------------------------------------------------===// -#include "PNaClTranslator.h" #include "IceCfg.h" #include "IceCfgNode.h" #include "IceClFlags.h" @@ -20,6 +19,7 @@ #include "IceInst.h" #include "IceOperand.h" #include "IceTypeConverter.h" +#include "PNaClTranslator.h" #include "llvm/Analysis/NaCl/PNaClABIProps.h" #include "llvm/Bitcode/NaCl/NaClBitcodeDecoders.h" #include "llvm/Bitcode/NaCl/NaClBitcodeHeader.h" @@ -852,7 +852,7 @@ } } - ~FunctionParser() override; + ~FunctionParser() override {}; // Set the next constant ID to the given constant C. void setNextConstantID(Ice::Constant *C) { @@ -860,8 +860,6 @@ } private: - // Timer for reading function bitcode and converting to ICE. - Ice::Timer TConvert; // The corresponding ICE function defined by the function block. Ice::Cfg *Func; // The index to the current basic block being built. @@ -1376,13 +1374,6 @@ } }; -FunctionParser::~FunctionParser() { - if (getFlags().SubzeroTimingEnabled) { - errs() << "[Subzero timing] Convert function " << Func->getFunctionName() - << ": " << TConvert.getElapsedSec() << " sec\n"; - } -} - void FunctionParser::ReportInvalidBinopOpcode(unsigned Opcode, Ice::Type Ty) { std::string Buffer; raw_string_ostream StrBuf(Buffer);
diff --git a/src/llvm2ice.cpp b/src/llvm2ice.cpp index 515e2fe..7f1fc38 100644 --- a/src/llvm2ice.cpp +++ b/src/llvm2ice.cpp
@@ -44,7 +44,6 @@ clEnumValN(Ice::IceV_RegOrigins, "orig", "Physical register origins"), clEnumValN(Ice::IceV_LinearScan, "regalloc", "Linear scan details"), clEnumValN(Ice::IceV_Frame, "frame", "Stack frame layout details"), - clEnumValN(Ice::IceV_Timing, "time", "Pass timing details"), clEnumValN(Ice::IceV_AddrOpt, "addropt", "Address mode optimization"), clEnumValN(Ice::IceV_All, "all", "Use all verbose options"), clEnumValN(Ice::IceV_Most, "most", @@ -175,6 +174,8 @@ Ice::GlobalContext Ctx(Ls, Os, VMask, TargetArch, OptLevel, TestPrefix, Flags); + static Ice::TimerIdT IDszmain = Ice::GlobalContext::getTimerID("szmain"); + Ice::TimerMarker T(IDszmain, &Ctx); int ErrorStatus = 0; if (BuildOnRead) { @@ -184,15 +185,11 @@ } else { // Parse the input LLVM IR file into a module. SMDiagnostic Err; - Ice::Timer T; + static Ice::TimerIdT IDparse = Ice::GlobalContext::getTimerID("parse"); + Ice::TimerMarker T1(IDparse, &Ctx); Module *Mod = NaClParseIRFile(IRFilename, InputFileFormat, Err, getGlobalContext()); - if (SubzeroTimingEnabled) { - std::cerr << "[Subzero timing] IR Parsing: " << T.getElapsedSec() - << " sec\n"; - } - if (!Mod) { Err.print(argv[0], errs()); return 1; @@ -202,6 +199,8 @@ Converter.convertToIce(); ErrorStatus = Converter.getErrorStatus(); } + if (SubzeroTimingEnabled) + Ctx.dumpTimers(); const bool FinalStats = true; Ctx.dumpStats("_FINAL_", FinalStats); return ErrorStatus;