X-Git-Url: http://plrg.eecs.uci.edu/git/?p=oota-llvm.git;a=blobdiff_plain;f=lib%2FSupport%2FTimer.cpp;h=f032ee5d30d04ef06f8b510574eee17daeddc4cc;hp=ede1dc96e82732fb7d8e82a56becebc4eb59520c;hb=df7186636e51e63281bd318234b7d97f25efe491;hpb=46d9a6494496d215e850f337b5a723c484212f80 diff --git a/lib/Support/Timer.cpp b/lib/Support/Timer.cpp index ede1dc96e82..f032ee5d30d 100644 --- a/lib/Support/Timer.cpp +++ b/lib/Support/Timer.cpp @@ -12,19 +12,17 @@ //===----------------------------------------------------------------------===// #include "llvm/Support/Timer.h" +#include "llvm/ADT/Statistic.h" +#include "llvm/ADT/StringMap.h" #include "llvm/Support/CommandLine.h" +#include "llvm/Support/FileSystem.h" +#include "llvm/Support/Format.h" #include "llvm/Support/ManagedStatic.h" -#include "llvm/Support/Streams.h" -#include "llvm/System/Process.h" -#include -#include -#include -#include +#include "llvm/Support/Mutex.h" +#include "llvm/Support/Process.h" +#include "llvm/Support/raw_ostream.h" using namespace llvm; -// GetLibSupportInfoOutputFile - Return a file stream to print our output on. -namespace llvm { extern std::ostream *GetLibSupportInfoOutputFile(); } - // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy // of constructor/destructor ordering being unspecified by C++. Basically the // problem is that a Statistic object gets destroyed, which ends up calling @@ -52,117 +50,105 @@ namespace { cl::Hidden, cl::location(getLibSupportInfoOutputFilename())); } -static TimerGroup *DefaultTimerGroup = 0; +// Return a file stream to print our output on. +std::unique_ptr llvm::CreateInfoOutputFile() { + const std::string &OutputFilename = getLibSupportInfoOutputFilename(); + if (OutputFilename.empty()) + return llvm::make_unique(2, false); // stderr. + if (OutputFilename == "-") + return llvm::make_unique(1, false); // stdout. + + // Append mode is used because the info output file is opened and closed + // each time -stats or -time-passes wants to print output to it. To + // compensate for this, the test-suite Makefiles have code to delete the + // info output file before running commands which write to it. + std::error_code EC; + auto Result = llvm::make_unique( + OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text); + if (!EC) + return Result; + + errs() << "Error opening info-output-file '" + << OutputFilename << " for appending!\n"; + return llvm::make_unique(2, false); // stderr. +} + + +static TimerGroup *DefaultTimerGroup = nullptr; static TimerGroup *getDefaultTimerGroup() { - TimerGroup* tmp = DefaultTimerGroup; + TimerGroup *tmp = DefaultTimerGroup; sys::MemoryFence(); + if (tmp) return tmp; + + sys::SmartScopedLock Lock(*TimerLock); + tmp = DefaultTimerGroup; if (!tmp) { - llvm_acquire_global_lock(); - tmp = DefaultTimerGroup; - if (!tmp) { - tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); - sys::MemoryFence(); - DefaultTimerGroup = tmp; - } - llvm_release_global_lock(); + tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); + sys::MemoryFence(); + DefaultTimerGroup = tmp; } - - return tmp; -} -Timer::Timer(const std::string &N) - : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), - Started(false), TG(getDefaultTimerGroup()) { - TG->addTimer(); + return tmp; } -Timer::Timer(const std::string &N, TimerGroup &tg) - : Elapsed(0), UserTime(0), SystemTime(0), MemUsed(0), PeakMem(0), Name(N), - Started(false), TG(&tg) { - TG->addTimer(); -} +//===----------------------------------------------------------------------===// +// Timer Implementation +//===----------------------------------------------------------------------===// -Timer::Timer(const Timer &T) { - TG = T.TG; - if (TG) TG->addTimer(); - operator=(T); +void Timer::init(StringRef N) { + assert(!TG && "Timer already initialized"); + Name.assign(N.begin(), N.end()); + Started = false; + TG = getDefaultTimerGroup(); + TG->addTimer(*this); } - -// 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; +void Timer::init(StringRef N, TimerGroup &tg) { + assert(!TG && "Timer already initialized"); + Name.assign(N.begin(), N.end()); + Started = false; + TG = &tg; + TG->addTimer(*this); } - Timer::~Timer() { - if (TG) { - if (Started) { - Started = false; - TG->addTimerToPrint(*this); - } - TG->removeTimer(); - } + if (!TG) return; // Never initialized, or already cleared. + TG->removeTimer(*this); } static inline size_t getMemUsage() { - if (TrackSpace) - return sys::Process::GetMallocUsage(); - return 0; + if (!TrackSpace) return 0; + return sys::Process::GetMallocUsage(); } -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); - sys::TimeValue user(0,0); - sys::TimeValue sys(0,0); - - ssize_t MemUsed = 0; + sys::TimeValue now(0,0), user(0,0), sys(0,0); + if (Start) { - MemUsed = getMemUsage(); - sys::Process::GetTimeUsage(now,user,sys); + Result.MemUsed = getMemUsage(); + sys::Process::GetTimeUsage(now, user, sys); } else { - sys::Process::GetTimeUsage(now,user,sys); - MemUsed = getMemUsage(); + sys::Process::GetTimeUsage(now, user, sys); + Result.MemUsed = getMemUsage(); } - Result.Elapsed = now.seconds() + now.microseconds() / 1000000.0; - Result.UserTime = user.seconds() + user.microseconds() / 1000000.0; - Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0; - Result.MemUsed = MemUsed; - + Result.WallTime = now.seconds() + now.microseconds() / 1000000.0; + Result.UserTime = user.seconds() + user.microseconds() / 1000000.0; + Result.SystemTime = sys.seconds() + sys.microseconds() / 1000000.0; return Result; } static ManagedStatic > ActiveTimers; void Timer::startTimer() { - sys::SmartScopedLock L(&Lock); Started = true; ActiveTimers->push_back(this); - TimeRecord TR = getTimeRecord(true); - Elapsed -= TR.Elapsed; - UserTime -= TR.UserTime; - SystemTime -= TR.SystemTime; - MemUsed -= TR.MemUsed; - PeakMemBase = TR.MemUsed; + Time -= TimeRecord::getCurrentTime(true); } void Timer::stopTimer() { - sys::SmartScopedLock L(&Lock); - 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(); @@ -174,44 +160,28 @@ void Timer::stopTimer() { } } -void Timer::sum(const Timer &T) { - if (&T < this) { - T.Lock.acquire(); - Lock.acquire(); - } else { - Lock.acquire(); - T.Lock.acquire(); - } +static void printVal(double Val, double Total, raw_ostream &OS) { + if (Total < 1e-7) // Avoid dividing by zero. + OS << " ----- "; + else + OS << format(" %7.4f (%5.1f%%)", Val, Val*100/Total); +} + +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(getWallTime(), Total.getWallTime(), OS); - Elapsed += T.Elapsed; - UserTime += T.UserTime; - SystemTime += T.SystemTime; - MemUsed += T.MemUsed; - PeakMem += T.PeakMem; + OS << " "; - if (&T < this) { - T.Lock.release(); - Lock.release(); - } else { - Lock.release(); - T.Lock.release(); - } + if (Total.getMemUsed()) + OS << format("%9" PRId64 " ", (int64_t)getMemUsed()); } -/// addPeakMemoryMeasurement - This method should be called whenever memory -/// usage needs to be checked. It adds a peak memory measurement to the -/// currently active timers, which will be printed when the timer group prints -/// -void Timer::addPeakMemoryMeasurement() { - size_t MemUsed = getMemUsage(); - - for (std::vector::iterator I = ActiveTimers->begin(), - E = ActiveTimers->end(); I != E; ++I) { - (*I)->Lock.acquire(); - (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase); - (*I)->Lock.release(); - } -} //===----------------------------------------------------------------------===// // NamedRegionTimer Implementation @@ -219,227 +189,195 @@ void Timer::addPeakMemoryMeasurement() { namespace { -typedef std::map Name2Timer; -typedef std::map > Name2Pair; +typedef StringMap Name2TimerMap; -} - -static ManagedStatic NamedTimers; - -static ManagedStatic NamedGroupedTimers; - -static Timer &getNamedRegionTimer(const std::string &Name) { - sys::SmartScopedLock L(&*TimerLock); - Name2Timer::iterator I = NamedTimers->find(Name); - if (I != NamedTimers->end()) - return I->second; +class Name2PairMap { + StringMap > Map; +public: + ~Name2PairMap() { + for (StringMap >::iterator + I = Map.begin(), E = Map.end(); I != E; ++I) + delete I->second.first; + } + + Timer &get(StringRef Name, StringRef GroupName) { + sys::SmartScopedLock L(*TimerLock); + + std::pair &GroupEntry = Map[GroupName]; + + if (!GroupEntry.first) + GroupEntry.first = new TimerGroup(GroupName); + + Timer &T = GroupEntry.second[Name]; + if (!T.isInitialized()) + T.init(Name, *GroupEntry.first); + return T; + } +}; - return NamedTimers->insert(I, std::make_pair(Name, Timer(Name)))->second; } -static Timer &getNamedRegionTimer(const std::string &Name, - const std::string &GroupName) { - sys::SmartScopedLock L(&*TimerLock); - - Name2Pair::iterator I = NamedGroupedTimers->find(GroupName); - if (I == NamedGroupedTimers->end()) { - TimerGroup TG(GroupName); - std::pair Pair(TG, Name2Timer()); - I = NamedGroupedTimers->insert(I, std::make_pair(GroupName, Pair)); - } - - 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))); +static ManagedStatic NamedTimers; +static ManagedStatic NamedGroupedTimers; - return J->second; +static Timer &getNamedRegionTimer(StringRef Name) { + sys::SmartScopedLock L(*TimerLock); + + Timer &T = (*NamedTimers)[Name]; + if (!T.isInitialized()) + T.init(Name); + return T; } -NamedRegionTimer::NamedRegionTimer(const std::string &Name) - : TimeRegion(getNamedRegionTimer(Name)) {} +NamedRegionTimer::NamedRegionTimer(StringRef Name, + bool Enabled) + : TimeRegion(!Enabled ? nullptr : &getNamedRegionTimer(Name)) {} -NamedRegionTimer::NamedRegionTimer(const std::string &Name, - const std::string &GroupName) - : TimeRegion(getNamedRegionTimer(Name, GroupName)) {} +NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName, + bool Enabled) + : TimeRegion(!Enabled ? nullptr : &NamedGroupedTimers->get(Name, GroupName)){} //===----------------------------------------------------------------------===// // TimerGroup Implementation //===----------------------------------------------------------------------===// -// printAlignedFP - Simulate the printf "%A.Bf" format, where A is the -// TotalWidth size, and B is the AfterDec size. -// -static void printAlignedFP(double Val, unsigned AfterDec, unsigned TotalWidth, - std::ostream &OS) { - assert(TotalWidth >= AfterDec+1 && "Bad FP Format!"); - OS.width(TotalWidth-AfterDec-1); - char OldFill = OS.fill(); - OS.fill(' '); - OS << (int)Val; // Integer part; - OS << "."; - OS.width(AfterDec); - OS.fill('0'); - unsigned ResultFieldSize = 1; - while (AfterDec--) ResultFieldSize *= 10; - OS << (int)(Val*ResultFieldSize) % ResultFieldSize; - OS.fill(OldFill); +/// TimerGroupList - This is the global list of TimerGroups, maintained by the +/// TimerGroup ctor/dtor and is protected by the TimerLock lock. +static TimerGroup *TimerGroupList = nullptr; + +TimerGroup::TimerGroup(StringRef name) + : Name(name.begin(), name.end()), FirstTimer(nullptr) { + + // Add the group to TimerGroupList. + sys::SmartScopedLock L(*TimerLock); + if (TimerGroupList) + TimerGroupList->Prev = &Next; + Next = TimerGroupList; + Prev = &TimerGroupList; + TimerGroupList = this; } -static void printVal(double Val, double Total, std::ostream &OS) { - if (Total < 1e-7) // Avoid dividing by zero... - OS << " ----- "; - else { - OS << " "; - printAlignedFP(Val, 4, 7, OS); - OS << " ("; - printAlignedFP(Val*100/Total, 1, 5, OS); - OS << "%)"; - } +TimerGroup::~TimerGroup() { + // If the timer group is destroyed before the timers it owns, accumulate and + // print the timing data. + while (FirstTimer) + removeTimer(*FirstTimer); + + // Remove the group from the TimerGroupList. + sys::SmartScopedLock L(*TimerLock); + *Prev = Next; + if (Next) + Next->Prev = Prev; } -void Timer::print(const Timer &Total, std::ostream &OS) { - if (&Total < this) { - Total.Lock.acquire(); - Lock.acquire(); - } else { - Lock.acquire(); - Total.Lock.acquire(); - } + +void TimerGroup::removeTimer(Timer &T) { + sys::SmartScopedLock L(*TimerLock); - if (Total.UserTime) - printVal(UserTime, Total.UserTime, OS); - if (Total.SystemTime) - printVal(SystemTime, Total.SystemTime, OS); - if (Total.getProcessTime()) - printVal(getProcessTime(), Total.getProcessTime(), OS); - printVal(Elapsed, Total.Elapsed, OS); + // If the timer was started, move its data to TimersToPrint. + if (T.Started) + TimersToPrint.push_back(std::make_pair(T.Time, T.Name)); - OS << " "; + T.TG = nullptr; + + // Unlink the timer from our list. + *T.Prev = T.Next; + if (T.Next) + T.Next->Prev = T.Prev; + + // Print the report when all timers in this group are destroyed if some of + // them were started. + if (FirstTimer || TimersToPrint.empty()) + return; - if (Total.MemUsed) { - OS.width(9); - OS << MemUsed << " "; - } - if (Total.PeakMem) { - if (PeakMem) { - OS.width(9); - OS << PeakMem << " "; - } else - OS << " "; - } - OS << Name << "\n"; + std::unique_ptr OutStream = CreateInfoOutputFile(); + PrintQueuedTimers(*OutStream); +} - Started = false; // Once printed, don't print again +void TimerGroup::addTimer(Timer &T) { + sys::SmartScopedLock L(*TimerLock); - if (&Total < this) { - Total.Lock.release(); - Lock.release(); - } else { - Lock.release(); - Total.Lock.release(); - } + // Add the timer to our list. + if (FirstTimer) + FirstTimer->Prev = &T.Next; + T.Next = FirstTimer; + T.Prev = &FirstTimer; + FirstTimer = &T; } -// GetLibSupportInfoOutputFile - Return a file stream to print our output on... -std::ostream * -llvm::GetLibSupportInfoOutputFile() { - std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename(); - if (LibSupportInfoOutputFilename.empty()) - return cerr.stream(); - if (LibSupportInfoOutputFilename == "-") - return cout.stream(); - - std::ostream *Result = new std::ofstream(LibSupportInfoOutputFilename.c_str(), - std::ios::app); - if (!Result->good()) { - cerr << "Error opening info-output-file '" - << LibSupportInfoOutputFilename << " for appending!\n"; - delete Result; - return cerr.stream(); +void TimerGroup::PrintQueuedTimers(raw_ostream &OS) { + // Sort the timers in descending order by amount of time taken. + std::sort(TimersToPrint.begin(), TimersToPrint.end()); + + TimeRecord Total; + for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) + Total += TimersToPrint[i].first; + + // Print out timing header. + OS << "===" << std::string(73, '-') << "===\n"; + // Figure out how many spaces to indent TimerGroup name. + unsigned Padding = (80-Name.length())/2; + if (Padding > 80) Padding = 0; // Don't allow "negative" numbers + OS.indent(Padding) << Name << '\n'; + OS << "===" << 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) + OS << format(" Total Execution Time: %5.4f seconds (%5.4f wall clock)\n", + Total.getProcessTime(), Total.getWallTime()); + OS << '\n'; + + if (Total.getUserTime()) + OS << " ---User Time---"; + if (Total.getSystemTime()) + OS << " --System Time--"; + if (Total.getProcessTime()) + OS << " --User+System--"; + OS << " ---Wall Time---"; + if (Total.getMemUsed()) + OS << " ---Mem---"; + OS << " --- 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 &Entry = TimersToPrint[e-i-1]; + Entry.first.print(Total, OS); + OS << Entry.second << '\n'; } - return Result; + + Total.print(Total, OS); + OS << "Total\n\n"; + OS.flush(); + + TimersToPrint.clear(); } - -void TimerGroup::removeTimer() { - sys::SmartScopedLock L(&*TimerLock); - if (--NumTimers == 0 && !TimersToPrint.empty()) { // Print timing report... - // Sort the timers in descending order by amount of time taken... - std::sort(TimersToPrint.begin(), TimersToPrint.end(), - std::greater()); - - // Figure out how many spaces to indent TimerGroup name... - unsigned Padding = (80-Name.length())/2; - if (Padding > 80) Padding = 0; // Don't allow "negative" numbers - - std::ostream *OutStream = GetLibSupportInfoOutputFile(); - - ++NumTimers; - { // Scope to contain Total timer... don't allow total timer to drop us to - // zero timers... - Timer Total("TOTAL"); - - for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) - Total.sum(TimersToPrint[i]); - - // 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: "; - - printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream); - *OutStream << " seconds ("; - printAlignedFP(Total.getWallTime(), 4, 5, *OutStream); - *OutStream << " 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---"; - if (Total.getPeakMem()) - *OutStream << " -PeakMem-"; - *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 << std::endl; // Flush output - } - --NumTimers; - - TimersToPrint.clear(); - - if (OutStream != cerr.stream() && OutStream != cout.stream()) - delete OutStream; // Close the file... +/// print - Print any started timers in this group and zero them. +void TimerGroup::print(raw_ostream &OS) { + sys::SmartScopedLock L(*TimerLock); + + // See if any of our timers were started, if so add them to TimersToPrint and + // reset them. + for (Timer *T = FirstTimer; T; T = T->Next) { + if (!T->Started) continue; + TimersToPrint.push_back(std::make_pair(T->Time, T->Name)); + + // Clear out the time. + T->Started = 0; + T->Time = TimeRecord(); } -} -void TimerGroup::addTimer() { - sys::SmartScopedLock L(&*TimerLock); - ++NumTimers; + // If any timers were started, print the group. + if (!TimersToPrint.empty()) + PrintQueuedTimers(OS); } -void TimerGroup::addTimerToPrint(const Timer &T) { - sys::SmartScopedLock L(&*TimerLock); - TimersToPrint.push_back(Timer(true, T)); -} +/// printAll - This static method prints all timers and clears them all out. +void TimerGroup::printAll(raw_ostream &OS) { + sys::SmartScopedLock L(*TimerLock); + for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next) + TG->print(OS); +}