fairly major rewrite of various timing related stuff.

llvm-svn: 99862
This commit is contained in:
Chris Lattner 2010-03-30 02:38:19 +00:00
parent ef30b48453
commit 65efe21d42
6 changed files with 188 additions and 220 deletions

View File

@ -413,7 +413,6 @@ private:
/// It batches all function passes and basic block pass managers together and
/// sequence them to process one function at a time before processing next
/// function.
class FPPassManager : public ModulePass, public PMDataManager {
public:
static char ID;
@ -462,8 +461,7 @@ public:
}
};
extern Timer *StartPassTimer(Pass *);
extern void StopPassTimer(Pass *, Timer *);
Timer *getPassTimer(Pass *);
}

View File

@ -16,15 +16,62 @@
#define LLVM_SUPPORT_TIMER_H
#include "llvm/System/DataTypes.h"
#include <cassert>
#include <string>
#include <vector>
#include <cassert>
#include <utility>
namespace llvm {
class Timer;
class TimerGroup;
class raw_ostream;
class TimeRecord {
double WallTime; // Wall clock time elapsed in seconds
double UserTime; // User time elapsed
double SystemTime; // System time elapsed
ssize_t MemUsed; // Memory allocated (in bytes)
public:
TimeRecord() : WallTime(0), UserTime(0), SystemTime(0), MemUsed(0) {}
/// getCurrentTime - Get the current time and memory usage. If Start is true
/// we get the memory usage before the time, otherwise we get time before
/// memory usage. This matters if the time to get the memory usage is
/// significant and shouldn't be counted as part of a duration.
static TimeRecord getCurrentTime(bool Start = true);
double getProcessTime() const { return UserTime+SystemTime; }
double getUserTime() const { return UserTime; }
double getSystemTime() const { return SystemTime; }
double getWallTime() const { return WallTime; }
ssize_t getMemUsed() const { return MemUsed; }
// operator< - Allow sorting.
bool operator<(const TimeRecord &T) const {
// Sort by Wall Time elapsed, as it is the only thing really accurate
return WallTime < T.WallTime;
}
void operator+=(const TimeRecord &RHS) {
WallTime += RHS.WallTime;
UserTime += RHS.UserTime;
SystemTime += RHS.SystemTime;
MemUsed += RHS.MemUsed;
}
void operator-=(const TimeRecord &RHS) {
WallTime -= RHS.WallTime;
UserTime -= RHS.UserTime;
SystemTime -= RHS.SystemTime;
MemUsed -= RHS.MemUsed;
}
/// print - Print the current timer to standard error, and reset the "Started"
/// flag.
void print(const TimeRecord &Total, raw_ostream &OS) const;
};
/// Timer - This class is used to track the amount of time spent between
/// invocations of its startTimer()/stopTimer() methods. Given appropriate OS
/// support it can also keep track of the RSS of the program at various points.
@ -34,35 +81,30 @@ class raw_ostream;
/// if they are never started.
///
class Timer {
double Elapsed; // Wall clock time elapsed in seconds
double UserTime; // User time elapsed
double SystemTime; // System time elapsed
ssize_t MemUsed; // Memory allocated (in bytes)
TimeRecord Time;
std::string Name; // The name of this time variable.
bool Started; // Has this time variable ever been started?
TimerGroup *TG; // The TimerGroup this Timer is in.
public:
explicit Timer(const std::string &N);
Timer(const std::string &N, TimerGroup &tg);
Timer(const Timer &T);
explicit Timer(const std::string &N) : TG(0) { init(N); }
Timer(const std::string &N, TimerGroup &tg) : TG(0) { init(N, tg); }
Timer(const Timer &RHS) : TG(0) {
assert(RHS.TG == 0 && "Can only copy uninitialized timers");
}
const Timer &operator=(const Timer &T) {
assert(TG == 0 && T.TG == 0 && "Can only assign uninit timers");
return *this;
}
~Timer();
private:
double getProcessTime() const { return UserTime+SystemTime; }
double getWallTime() const { return Elapsed; }
ssize_t getMemUsed() const { return MemUsed; }
public:
std::string getName() const { return Name; }
const Timer &operator=(const Timer &T);
// Create an uninitialized timer, client must use 'init'.
explicit Timer() : TG(0) {}
void init(const std::string &N);
void init(const std::string &N, TimerGroup &tg);
const std::string &getName() const { return Name; }
bool isInitialized() const { return TG != 0; }
// operator< - Allow sorting.
bool operator<(const Timer &T) const {
// Sort by Wall Time elapsed, as it is the only thing really accurate
return Elapsed < T.Elapsed;
}
bool operator>(const Timer &T) const { return T.operator<(*this); }
/// startTimer - Start the timer running. Time between calls to
/// startTimer/stopTimer is counted by the Timer class. Note that these calls
/// must be correctly paired.
@ -73,19 +115,8 @@ public:
///
void stopTimer();
/// print - Print the current timer to standard error, and reset the "Started"
/// flag.
void print(const Timer &Total, raw_ostream &OS);
private:
friend class TimerGroup;
// Copy ctor, initialize with no TG member.
Timer(bool, const Timer &T);
/// sum - Add the time accumulated in the specified timer into this timer.
///
void sum(const Timer &T);
};
@ -132,9 +163,13 @@ struct NamedRegionTimer : public TimeRegion {
class TimerGroup {
std::string Name;
unsigned NumTimers;
std::vector<Timer> TimersToPrint;
std::vector<std::pair<TimeRecord, std::string> > TimersToPrint;
public:
explicit TimerGroup(const std::string &name) : Name(name), NumTimers(0) {}
explicit TimerGroup() : NumTimers(0) {}
void setName(const std::string &name) { Name = name; }
~TimerGroup() {
assert(NumTimers == 0 &&
"TimerGroup destroyed before all contained timers!");
@ -144,7 +179,7 @@ private:
friend class Timer;
void addTimer();
void removeTimer();
void addTimerToPrint(const Timer &T);
void addTimerToPrint(const TimeRecord &T, const std::string &Name);
};
} // End llvm namespace

View File

@ -17,12 +17,13 @@
#define DEBUG_TYPE "cgscc-passmgr"
#include "llvm/CallGraphSCCPass.h"
#include "llvm/IntrinsicInst.h"
#include "llvm/Function.h"
#include "llvm/PassManagers.h"
#include "llvm/Analysis/CallGraph.h"
#include "llvm/ADT/SCCIterator.h"
#include "llvm/PassManagers.h"
#include "llvm/Function.h"
#include "llvm/Support/Debug.h"
#include "llvm/IntrinsicInst.h"
#include "llvm/Support/Timer.h"
#include "llvm/Support/raw_ostream.h"
using namespace llvm;
@ -102,9 +103,10 @@ bool CGPassManager::RunPassOnSCC(Pass *P, std::vector<CallGraphNode*> &CurSCC,
CallGraphUpToDate = true;
}
Timer *T = StartPassTimer(CGSP);
Changed = CGSP->runOnSCC(CurSCC);
StopPassTimer(CGSP, T);
{
TimeRegion PassTimer(getPassTimer(CGSP));
Changed = CGSP->runOnSCC(CurSCC);
}
// After the CGSCCPass is done, when assertions are enabled, use
// RefreshCallGraph to verify that the callgraph was correctly updated.
@ -125,9 +127,8 @@ bool CGPassManager::RunPassOnSCC(Pass *P, std::vector<CallGraphNode*> &CurSCC,
for (unsigned i = 0, e = CurSCC.size(); i != e; ++i) {
if (Function *F = CurSCC[i]->getFunction()) {
dumpPassInfo(P, EXECUTION_MSG, ON_FUNCTION_MSG, F->getName());
Timer *T = StartPassTimer(FPP);
TimeRegion PassTimer(getPassTimer(FPP));
Changed |= FPP->runOnFunction(*F);
StopPassTimer(FPP, T);
}
}

View File

@ -14,6 +14,7 @@
//===----------------------------------------------------------------------===//
#include "llvm/Analysis/LoopPass.h"
#include "llvm/Support/Timer.h"
using namespace llvm;
//===----------------------------------------------------------------------===//
@ -228,9 +229,9 @@ bool LPPassManager::runOnFunction(Function &F) {
{
PassManagerPrettyStackEntry X(P, *CurrentLoop->getHeader());
Timer *T = StartPassTimer(P);
TimeRegion PassTimer(getPassTimer(P));
Changed |= P->runOnLoop(CurrentLoop, *this);
StopPassTimer(P, T);
}
if (Changed)
@ -245,9 +246,10 @@ bool LPPassManager::runOnFunction(Function &F) {
// is a function pass and it's really expensive to verify every
// loop in the function every time. That level of checking can be
// enabled with the -verify-loop-info option.
Timer *T = StartPassTimer(LI);
CurrentLoop->verifyLoop();
StopPassTimer(LI, T);
{
TimeRegion PassTimer(getPassTimer(LI));
CurrentLoop->verifyLoop();
}
// Then call the regular verifyAnalysis functions.
verifyPreservedAnalysis(P);

View File

@ -19,6 +19,7 @@
#include "llvm/Support/Format.h"
#include "llvm/System/Mutex.h"
#include "llvm/System/Process.h"
#include "llvm/ADT/StringMap.h"
#include <map>
using namespace llvm;
@ -95,37 +96,28 @@ static TimerGroup *getDefaultTimerGroup() {
// Timer Implementation
//===----------------------------------------------------------------------===//
Timer::Timer(const std::string &N)
: Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), Name(N),
Started(false), TG(getDefaultTimerGroup()) {
void Timer::init(const std::string &N) {
assert(TG == 0 && "Timer already initialized");
Name = N;
Started = false;
TG = getDefaultTimerGroup();
TG->addTimer();
}
Timer::Timer(const std::string &N, TimerGroup &tg)
: Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), Name(N),
Started(false), TG(&tg) {
void Timer::init(const std::string &N, TimerGroup &tg) {
assert(TG == 0 && "Timer already initialized");
Name = N;
Started = false;
TG = &tg;
TG->addTimer();
}
Timer::Timer(const Timer &T) {
TG = T.TG;
if (TG) TG->addTimer();
operator=(T);
}
// Copy ctor, initialize with no TG member.
Timer::Timer(bool, const Timer &T) {
TG = T.TG; // Avoid assertion in operator=
operator=(T); // Copy contents
TG = 0;
}
Timer::~Timer() {
if (!TG) return;
if (!TG) return; // Never initialized.
if (Started) {
Started = false;
TG->addTimerToPrint(*this);
TG->addTimerToPrint(Time, Name);
}
TG->removeTimer();
}
@ -136,12 +128,7 @@ static inline size_t getMemUsage() {
return 0;
}
struct TimeRecord {
double Elapsed, UserTime, SystemTime;
ssize_t MemUsed;
};
static TimeRecord getTimeRecord(bool Start) {
TimeRecord TimeRecord::getCurrentTime(bool Start) {
TimeRecord Result;
sys::TimeValue now(0,0);
@ -157,9 +144,9 @@ static TimeRecord getTimeRecord(bool Start) {
MemUsed = getMemUsage();
}
Result.Elapsed = now.seconds() + now.microseconds() / 1000000.0;
Result.WallTime = now.seconds() + now.microseconds() / 1000000.0;
Result.UserTime = user.seconds() + user.microseconds() / 1000000.0;
Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0;
Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0;
Result.MemUsed = MemUsed;
return Result;
}
@ -169,19 +156,11 @@ static ManagedStatic<std::vector<Timer*> > ActiveTimers;
void Timer::startTimer() {
Started = true;
ActiveTimers->push_back(this);
TimeRecord TR = getTimeRecord(true);
Elapsed -= TR.Elapsed;
UserTime -= TR.UserTime;
SystemTime -= TR.SystemTime;
MemUsed -= TR.MemUsed;
Time -= TimeRecord::getCurrentTime(true);
}
void Timer::stopTimer() {
TimeRecord TR = getTimeRecord(false);
Elapsed += TR.Elapsed;
UserTime += TR.UserTime;
SystemTime += TR.SystemTime;
MemUsed += TR.MemUsed;
Time += TimeRecord::getCurrentTime(false);
if (ActiveTimers->back() == this) {
ActiveTimers->pop_back();
@ -193,25 +172,6 @@ void Timer::stopTimer() {
}
}
void Timer::sum(const Timer &T) {
Elapsed += T.Elapsed;
UserTime += T.UserTime;
SystemTime += T.SystemTime;
MemUsed += T.MemUsed;
}
const Timer &Timer::operator=(const Timer &T) {
Elapsed = T.Elapsed;
UserTime = T.UserTime;
SystemTime = T.SystemTime;
MemUsed = T.MemUsed;
Name = T.Name;
Started = T.Started;
assert(TG == T.TG && "Can only assign timers in the same TimerGroup!");
return *this;
}
static void printVal(double Val, double Total, raw_ostream &OS) {
if (Total < 1e-7) // Avoid dividing by zero.
OS << " ----- ";
@ -221,23 +181,19 @@ static void printVal(double Val, double Total, raw_ostream &OS) {
}
}
void Timer::print(const Timer &Total, raw_ostream &OS) {
if (Total.UserTime)
printVal(UserTime, Total.UserTime, OS);
if (Total.SystemTime)
printVal(SystemTime, Total.SystemTime, OS);
void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
if (Total.getUserTime())
printVal(getUserTime(), Total.getUserTime(), OS);
if (Total.getSystemTime())
printVal(getSystemTime(), Total.getSystemTime(), OS);
if (Total.getProcessTime())
printVal(getProcessTime(), Total.getProcessTime(), OS);
printVal(Elapsed, Total.Elapsed, OS);
printVal(getWallTime(), Total.getWallTime(), OS);
OS << " ";
if (Total.MemUsed)
OS << format("%9lld", (long long)MemUsed) << " ";
OS << Name << "\n";
Started = false; // Once printed, don't print again
if (Total.getMemUsed())
OS << format("%9lld", (long long)getMemUsed()) << " ";
}
@ -245,40 +201,35 @@ void Timer::print(const Timer &Total, raw_ostream &OS) {
// NamedRegionTimer Implementation
//===----------------------------------------------------------------------===//
typedef std::map<std::string, Timer> Name2Timer;
typedef std::map<std::string, std::pair<TimerGroup, Name2Timer> > Name2Pair;
typedef StringMap<Timer> Name2TimerMap;
typedef StringMap<std::pair<TimerGroup, Name2TimerMap> > Name2PairMap;
static ManagedStatic<Name2Timer> NamedTimers;
static ManagedStatic<Name2Pair> NamedGroupedTimers;
static ManagedStatic<Name2TimerMap> NamedTimers;
static ManagedStatic<Name2PairMap> NamedGroupedTimers;
static Timer &getNamedRegionTimer(const std::string &Name) {
sys::SmartScopedLock<true> L(*TimerLock);
Name2Timer::iterator I = NamedTimers->find(Name);
if (I != NamedTimers->end())
return I->second;
return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second;
Timer &T = (*NamedTimers)[Name];
if (!T.isInitialized())
T.init(Name);
return T;
}
static Timer &getNamedRegionTimer(const std::string &Name,
const std::string &GroupName) {
sys::SmartScopedLock<true> L(*TimerLock);
Name2Pair::iterator I = NamedGroupedTimers->find(GroupName);
if (I == NamedGroupedTimers->end()) {
TimerGroup TG(GroupName);
std::pair<TimerGroup, Name2Timer> Pair(TG, Name2Timer());
I = NamedGroupedTimers->insert(I, std::make_pair(GroupName, Pair));
}
std::pair<TimerGroup, Name2TimerMap> &GroupEntry =
(*NamedGroupedTimers)[GroupName];
Name2Timer::iterator J = I->second.second.find(Name);
if (J == I->second.second.end())
J = I->second.second.insert(J,
std::make_pair(Name,
Timer(Name,
I->second.first)));
if (GroupEntry.second.empty())
GroupEntry.first.setName(GroupName);
return J->second;
Timer &T = GroupEntry.second[Name];
if (!T.isInitialized())
T.init(Name);
return T;
}
NamedRegionTimer::NamedRegionTimer(const std::string &Name)
@ -298,8 +249,7 @@ void TimerGroup::removeTimer() {
return; // Don't print timing report.
// Sort the timers in descending order by amount of time taken.
std::sort(TimersToPrint.begin(), TimersToPrint.end(),
std::greater<Timer>());
std::sort(TimersToPrint.begin(), TimersToPrint.end());
// Figure out how many spaces to indent TimerGroup name.
unsigned Padding = (80-Name.length())/2;
@ -307,50 +257,46 @@ void TimerGroup::removeTimer() {
raw_ostream *OutStream = GetLibSupportInfoOutputFile();
++NumTimers;
{ // Scope to contain Total timer: don't allow total timer to drop us to
// zero timers.
Timer Total("TOTAL");
TimeRecord Total;
for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
Total += TimersToPrint[i].first;
for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
Total.sum(TimersToPrint[i]);
// Print out timing header.
*OutStream << "===" << std::string(73, '-') << "===\n";
OutStream->indent(Padding) << Name << '\n';
*OutStream << "===" << std::string(73, '-') << "===\n";
// Print out timing header.
*OutStream << "===" << std::string(73, '-') << "===\n"
<< std::string(Padding, ' ') << Name << "\n"
<< "===" << std::string(73, '-')
<< "===\n";
// If this is not an collection of ungrouped times, print the total time.
// Ungrouped timers don't really make sense to add up. We still print the
// TOTAL line to make the percentages make sense.
if (this != DefaultTimerGroup) {
*OutStream << " Total Execution Time: ";
*OutStream << format("%5.4f", Total.getProcessTime()) << " seconds (";
*OutStream << format("%5.4f", Total.getWallTime()) << " wall clock)\n";
}
*OutStream << "\n";
if (Total.UserTime)
*OutStream << " ---User Time---";
if (Total.SystemTime)
*OutStream << " --System Time--";
if (Total.getProcessTime())
*OutStream << " --User+System--";
*OutStream << " ---Wall Time---";
if (Total.getMemUsed())
*OutStream << " ---Mem---";
*OutStream << " --- Name ---\n";
// Loop through all of the timing data, printing it out.
for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
TimersToPrint[i].print(Total, *OutStream);
Total.print(Total, *OutStream);
*OutStream << '\n';
OutStream->flush();
// If this is not an collection of ungrouped times, print the total time.
// Ungrouped timers don't really make sense to add up. We still print the
// TOTAL line to make the percentages make sense.
if (this != DefaultTimerGroup) {
*OutStream << " Total Execution Time: ";
*OutStream << format("%5.4f", Total.getProcessTime()) << " seconds (";
*OutStream << format("%5.4f", Total.getWallTime()) << " wall clock)\n";
}
--NumTimers;
*OutStream << "\n";
if (Total.getUserTime())
*OutStream << " ---User Time---";
if (Total.getSystemTime())
*OutStream << " --System Time--";
if (Total.getProcessTime())
*OutStream << " --User+System--";
*OutStream << " ---Wall Time---";
if (Total.getMemUsed())
*OutStream << " ---Mem---";
*OutStream << " --- Name ---\n";
// Loop through all of the timing data, printing it out.
for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
Entry.first.print(Total, *OutStream);
*OutStream << Entry.second << '\n';
}
Total.print(Total, *OutStream);
*OutStream << "Total\n\n";
OutStream->flush();
TimersToPrint.clear();
@ -363,8 +309,8 @@ void TimerGroup::addTimer() {
++NumTimers;
}
void TimerGroup::addTimerToPrint(const Timer &T) {
void TimerGroup::addTimerToPrint(const TimeRecord &T, const std::string &Name) {
sys::SmartScopedLock<true> L(*TimerLock);
TimersToPrint.push_back(Timer(true, T));
TimersToPrint.push_back(std::make_pair(T, Name));
}

View File

@ -378,7 +378,7 @@ namespace {
static ManagedStatic<sys::SmartMutex<true> > TimingInfoMutex;
class TimingInfo {
std::map<Pass*, Timer> TimingData;
DenseMap<Pass*, Timer> TimingData;
TimerGroup TG;
public:
@ -397,19 +397,16 @@ public:
// null. It may be called multiple times.
static void createTheTimeInfo();
/// passStarted - This method creates a timer for the given pass if it doesn't
/// already have one, and starts the timer.
Timer *passStarted(Pass *P) {
/// getPassTimer - Return the timer for the specified pass if it exists.
Timer *getPassTimer(Pass *P) {
if (P->getAsPMDataManager())
return 0;
sys::SmartScopedLock<true> Lock(*TimingInfoMutex);
std::map<Pass*, Timer>::iterator I = TimingData.find(P);
if (I == TimingData.end())
I=TimingData.insert(std::make_pair(P, Timer(P->getPassName(), TG))).first;
Timer *T = &I->second;
T->startTimer();
return T;
Timer &T = TimingData[P];
if (!T.isInitialized())
T.init(P->getPassName(), TG);
return &T;
}
};
@ -704,11 +701,8 @@ void PMDataManager::verifyPreservedAnalysis(Pass *P) {
E = PreservedSet.end(); I != E; ++I) {
AnalysisID AID = *I;
if (Pass *AP = findAnalysisPass(AID, true)) {
Timer *T = 0;
if (TheTimeInfo) T = TheTimeInfo->passStarted(AP);
TimeRegion PassTimer(getPassTimer(AP));
AP->verifyAnalysis();
if (T) T->stopTimer();
}
}
}
@ -792,10 +786,9 @@ void PMDataManager::freePass(Pass *P, StringRef Msg,
{
// If the pass crashes releasing memory, remember this.
PassManagerPrettyStackEntry X(P);
Timer *T = StartPassTimer(P);
TimeRegion PassTimer(getPassTimer(P));
P->releaseMemory();
StopPassTimer(P, T);
}
if (const PassInfo *PI = P->getPassInfo()) {
@ -1128,10 +1121,9 @@ bool BBPassManager::runOnFunction(Function &F) {
{
// If the pass crashes, remember this.
PassManagerPrettyStackEntry X(BP, *I);
Timer *T = StartPassTimer(BP);
TimeRegion PassTimer(getPassTimer(BP));
LocalChanged |= BP->runOnBasicBlock(*I);
StopPassTimer(BP, T);
}
Changed |= LocalChanged;
@ -1345,10 +1337,9 @@ bool FPPassManager::runOnFunction(Function &F) {
{
PassManagerPrettyStackEntry X(FP, F);
TimeRegion PassTimer(getPassTimer(FP));
Timer *T = StartPassTimer(FP);
LocalChanged |= FP->runOnFunction(F);
StopPassTimer(FP, T);
}
Changed |= LocalChanged;
@ -1420,9 +1411,9 @@ MPPassManager::runOnModule(Module &M) {
{
PassManagerPrettyStackEntry X(MP, M);
Timer *T = StartPassTimer(MP);
TimeRegion PassTimer(getPassTimer(MP));
LocalChanged |= MP->runOnModule(M);
StopPassTimer(MP, T);
}
Changed |= LocalChanged;
@ -1559,17 +1550,12 @@ void TimingInfo::createTheTimeInfo() {
}
/// If TimingInfo is enabled then start pass timer.
Timer *llvm::StartPassTimer(Pass *P) {
Timer *llvm::getPassTimer(Pass *P) {
if (TheTimeInfo)
return TheTimeInfo->passStarted(P);
return TheTimeInfo->getPassTimer(P);
return 0;
}
/// If TimingInfo is enabled then stop pass timer.
void llvm::StopPassTimer(Pass *P, Timer *T) {
if (T) T->stopTimer();
}
//===----------------------------------------------------------------------===//
// PMStack implementation
//