X-Git-Url: http://demsky.eecs.uci.edu/git/?a=blobdiff_plain;f=lib%2FSupport%2FTimer.cpp;h=4bdfac298cc0c74eaab2c96f4575bc450a17bef3;hb=c93b4cff89d85a13d4eaf1551af9fab276b88450;hp=4b273b02ff9184f3333840ff697189dc3783961f;hpb=aeb47b8db9246fc0d5d6e437225fe84524da9202;p=oota-llvm.git diff --git a/lib/Support/Timer.cpp b/lib/Support/Timer.cpp index 4b273b02ff9..4bdfac298cc 100644 --- a/lib/Support/Timer.cpp +++ b/lib/Support/Timer.cpp @@ -1,50 +1,53 @@ //===-- Timer.cpp - Interval Timing Support -------------------------------===// -// +// // The LLVM Compiler Infrastructure // -// This file was developed by the LLVM research group and is distributed under -// the University of Illinois Open Source License. See LICENSE.TXT for details. -// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// //===----------------------------------------------------------------------===// // // Interval Timing implementation. // //===----------------------------------------------------------------------===// +#include "llvm/Support/Debug.h" #include "llvm/Support/Timer.h" #include "llvm/Support/CommandLine.h" +#include "llvm/Support/ManagedStatic.h" +#include "llvm/Support/raw_ostream.h" +#include "llvm/Support/Format.h" #include "llvm/System/Process.h" #include -#include #include -#include #include - using namespace llvm; // GetLibSupportInfoOutputFile - Return a file stream to print our output on. -namespace llvm { extern std::ostream *GetLibSupportInfoOutputFile(); } +namespace llvm { extern raw_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 +// problem is that a Statistic object gets destroyed, which ends up calling // 'GetLibSupportInfoOutputFile()' (below), which calls this function. // LibSupportInfoOutputFilename used to be a global variable, but sometimes it // would get destroyed before the Statistic, causing havoc to ensue. We "fix" // this by creating the string the first time it is needed and never destroying // it. +static ManagedStatic LibSupportInfoOutputFilename; static std::string &getLibSupportInfoOutputFilename() { - static std::string *LibSupportInfoOutputFilename = new std::string(); return *LibSupportInfoOutputFilename; } +static ManagedStatic > TimerLock; + namespace { - cl::opt + static cl::opt TrackSpace("track-memory", cl::desc("Enable -time-passes memory " "tracking (this may be slow)"), cl::Hidden); - cl::opt + static cl::opt InfoOutputFilename("info-output-file", cl::value_desc("filename"), cl::desc("File to append -stats and -timer output to"), cl::Hidden, cl::location(getLibSupportInfoOutputFilename())); @@ -52,8 +55,20 @@ namespace { static TimerGroup *DefaultTimerGroup = 0; static TimerGroup *getDefaultTimerGroup() { - if (DefaultTimerGroup) return DefaultTimerGroup; - return DefaultTimerGroup = new TimerGroup("Miscellaneous Ungrouped Timers"); + TimerGroup* tmp = DefaultTimerGroup; + sys::MemoryFence(); + if (!tmp) { + llvm_acquire_global_lock(); + tmp = DefaultTimerGroup; + if (!tmp) { + tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); + sys::MemoryFence(); + DefaultTimerGroup = tmp; + } + llvm_release_global_lock(); + } + + return tmp; } Timer::Timer(const std::string &N) @@ -93,7 +108,7 @@ Timer::~Timer() { } } -static inline long getMemUsage() { +static inline size_t getMemUsage() { if (TrackSpace) return sys::Process::GetMallocUsage(); return 0; @@ -101,7 +116,7 @@ static inline long getMemUsage() { struct TimeRecord { double Elapsed, UserTime, SystemTime; - long MemUsed; + ssize_t MemUsed; }; static TimeRecord getTimeRecord(bool Start) { @@ -111,13 +126,13 @@ static TimeRecord getTimeRecord(bool Start) { sys::TimeValue user(0,0); sys::TimeValue sys(0,0); - long MemUsed = 0; + ssize_t MemUsed = 0; if (Start) { - sys::Process::GetTimeUsage(now,user,sys); MemUsed = getMemUsage(); + sys::Process::GetTimeUsage(now,user,sys); } else { - MemUsed = getMemUsage(); sys::Process::GetTimeUsage(now,user,sys); + MemUsed = getMemUsage(); } Result.Elapsed = now.seconds() + now.microseconds() / 1000000.0; @@ -128,33 +143,35 @@ static TimeRecord getTimeRecord(bool Start) { return Result; } -static std::vector ActiveTimers; +static ManagedStatic > ActiveTimers; void Timer::startTimer() { + sys::SmartScopedLock L(*TimerLock); 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; - ActiveTimers.push_back(this); } void Timer::stopTimer() { + sys::SmartScopedLock L(*TimerLock); TimeRecord TR = getTimeRecord(false); Elapsed += TR.Elapsed; UserTime += TR.UserTime; SystemTime += TR.SystemTime; MemUsed += TR.MemUsed; - if (ActiveTimers.back() == this) { - ActiveTimers.pop_back(); + if (ActiveTimers->back() == this) { + ActiveTimers->pop_back(); } else { std::vector::iterator I = - std::find(ActiveTimers.begin(), ActiveTimers.end(), this); - assert(I != ActiveTimers.end() && "stop but no startTimer?"); - ActiveTimers.erase(I); + std::find(ActiveTimers->begin(), ActiveTimers->end(), this); + assert(I != ActiveTimers->end() && "stop but no startTimer?"); + ActiveTimers->erase(I); } } @@ -171,10 +188,11 @@ void Timer::sum(const Timer &T) { /// currently active timers, which will be printed when the timer group prints /// void Timer::addPeakMemoryMeasurement() { - long MemUsed = getMemUsage(); + sys::SmartScopedLock L(*TimerLock); + size_t MemUsed = getMemUsage(); - for (std::vector::iterator I = ActiveTimers.begin(), - E = ActiveTimers.end(); I != E; ++I) + for (std::vector::iterator I = ActiveTimers->begin(), + E = ActiveTimers->end(); I != E; ++I) (*I)->PeakMem = std::max((*I)->PeakMem, MemUsed-(*I)->PeakMemBase); } @@ -182,56 +200,70 @@ void Timer::addPeakMemoryMeasurement() { // NamedRegionTimer Implementation //===----------------------------------------------------------------------===// -static Timer &getNamedRegionTimer(const std::string &Name) { - static std::map NamedTimers; +namespace { + +typedef std::map Name2Timer; +typedef std::map > Name2Pair; + +} - std::map::iterator I = NamedTimers.lower_bound(Name); - if (I != NamedTimers.end() && I->first == Name) +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; - return NamedTimers.insert(I, std::make_pair(Name, Timer(Name)))->second; + 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))); + + return J->second; } NamedRegionTimer::NamedRegionTimer(const std::string &Name) : TimeRegion(getNamedRegionTimer(Name)) {} +NamedRegionTimer::NamedRegionTimer(const std::string &Name, + const std::string &GroupName) + : TimeRegion(getNamedRegionTimer(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); -} -static void printVal(double Val, double Total, std::ostream &OS) { +static void printVal(double Val, double Total, raw_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 << "%)"; + OS << " " << format("%7.4f", Val) << " ("; + OS << format("%5.1f", Val*100/Total) << "%)"; } } -void Timer::print(const Timer &Total, std::ostream &OS) { +void Timer::print(const Timer &Total, raw_ostream &OS) { + sys::SmartScopedLock L(*TimerLock); if (Total.UserTime) printVal(UserTime, Total.UserTime, OS); if (Total.SystemTime) @@ -239,17 +271,15 @@ void Timer::print(const Timer &Total, std::ostream &OS) { if (Total.getProcessTime()) printVal(getProcessTime(), Total.getProcessTime(), OS); printVal(Elapsed, Total.Elapsed, OS); - + OS << " "; if (Total.MemUsed) { - OS.width(9); - OS << MemUsed << " "; + OS << format("%9lld", (long long)MemUsed) << " "; } if (Total.PeakMem) { if (PeakMem) { - OS.width(9); - OS << PeakMem << " "; + OS << format("%9lld", (long long)PeakMem) << " "; } else OS << " "; } @@ -259,27 +289,30 @@ void Timer::print(const Timer &Total, std::ostream &OS) { } // GetLibSupportInfoOutputFile - Return a file stream to print our output on... -std::ostream * +raw_ostream * llvm::GetLibSupportInfoOutputFile() { std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename(); if (LibSupportInfoOutputFilename.empty()) - return &std::cerr; + return &errs(); if (LibSupportInfoOutputFilename == "-") - return &std::cout; - - std::ostream *Result = new std::ofstream(LibSupportInfoOutputFilename.c_str(), - std::ios::app); - if (!Result->good()) { - std::cerr << "Error opening info-output-file '" - << LibSupportInfoOutputFilename << " for appending!\n"; - delete Result; - return &std::cerr; - } - return Result; + return &outs(); + + + std::string Error; + raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(), + Error, raw_fd_ostream::F_Append); + if (Error.empty()) + return Result; + + errs() << "Error opening info-output-file '" + << LibSupportInfoOutputFilename << " for appending!\n"; + delete Result; + return &errs(); } 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(), @@ -289,26 +322,32 @@ void TimerGroup::removeTimer() { unsigned Padding = (80-Name.length())/2; if (Padding > 80) Padding = 0; // Don't allow "negative" numbers - std::ostream *OutStream = GetLibSupportInfoOutputFile(); + raw_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 Total Execution Time: "; + << "===\n"; - printAlignedFP(Total.getProcessTime(), 4, 5, *OutStream); - *OutStream << " seconds ("; - printAlignedFP(Total.getWallTime(), 4, 5, *OutStream); - *OutStream << " wall clock)\n\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---"; @@ -322,26 +361,31 @@ void TimerGroup::removeTimer() { 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 + *OutStream << '\n'; + OutStream->flush(); } --NumTimers; TimersToPrint.clear(); - if (OutStream != &std::cerr && OutStream != &std::cout) + if (OutStream != &errs() && OutStream != &outs() && OutStream != &dbgs()) delete OutStream; // Close the file... } +} - // Delete default timer group! - if (NumTimers == 0 && this == DefaultTimerGroup) { - delete DefaultTimerGroup; - DefaultTimerGroup = 0; - } +void TimerGroup::addTimer() { + sys::SmartScopedLock L(*TimerLock); + ++NumTimers; +} + +void TimerGroup::addTimerToPrint(const Timer &T) { + sys::SmartScopedLock L(*TimerLock); + TimersToPrint.push_back(Timer(true, T)); }