LLVM  mainline
Timer.cpp
Go to the documentation of this file.
00001 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
00002 //
00003 //                     The LLVM Compiler Infrastructure
00004 //
00005 // This file is distributed under the University of Illinois Open Source
00006 // License. See LICENSE.TXT for details.
00007 //
00008 //===----------------------------------------------------------------------===//
00009 //
00010 // Interval Timing implementation.
00011 //
00012 //===----------------------------------------------------------------------===//
00013 
00014 #include "llvm/Support/Timer.h"
00015 #include "llvm/ADT/Statistic.h"
00016 #include "llvm/ADT/StringMap.h"
00017 #include "llvm/Support/CommandLine.h"
00018 #include "llvm/Support/FileSystem.h"
00019 #include "llvm/Support/Format.h"
00020 #include "llvm/Support/ManagedStatic.h"
00021 #include "llvm/Support/Mutex.h"
00022 #include "llvm/Support/Process.h"
00023 #include "llvm/Support/raw_ostream.h"
00024 using namespace llvm;
00025 
00026 // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
00027 // of constructor/destructor ordering being unspecified by C++.  Basically the
00028 // problem is that a Statistic object gets destroyed, which ends up calling
00029 // 'GetLibSupportInfoOutputFile()' (below), which calls this function.
00030 // LibSupportInfoOutputFilename used to be a global variable, but sometimes it
00031 // would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
00032 // this by creating the string the first time it is needed and never destroying
00033 // it.
00034 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
00035 static std::string &getLibSupportInfoOutputFilename() {
00036   return *LibSupportInfoOutputFilename;
00037 }
00038 
00039 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
00040 
00041 namespace {
00042   static cl::opt<bool>
00043   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
00044                                       "tracking (this may be slow)"),
00045              cl::Hidden);
00046 
00047   static cl::opt<std::string, true>
00048   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
00049                      cl::desc("File to append -stats and -timer output to"),
00050                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
00051 }
00052 
00053 // Return a file stream to print our output on.
00054 std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
00055   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
00056   if (OutputFilename.empty())
00057     return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
00058   if (OutputFilename == "-")
00059     return llvm::make_unique<raw_fd_ostream>(1, false); // stdout.
00060 
00061   // Append mode is used because the info output file is opened and closed
00062   // each time -stats or -time-passes wants to print output to it. To
00063   // compensate for this, the test-suite Makefiles have code to delete the
00064   // info output file before running commands which write to it.
00065   std::error_code EC;
00066   auto Result = llvm::make_unique<raw_fd_ostream>(
00067       OutputFilename, EC, sys::fs::F_Append | sys::fs::F_Text);
00068   if (!EC)
00069     return Result;
00070 
00071   errs() << "Error opening info-output-file '"
00072     << OutputFilename << " for appending!\n";
00073   return llvm::make_unique<raw_fd_ostream>(2, false); // stderr.
00074 }
00075 
00076 
00077 static TimerGroup *DefaultTimerGroup = nullptr;
00078 static TimerGroup *getDefaultTimerGroup() {
00079   TimerGroup *tmp = DefaultTimerGroup;
00080   sys::MemoryFence();
00081   if (tmp) return tmp;
00082   
00083   sys::SmartScopedLock<true> Lock(*TimerLock);
00084   tmp = DefaultTimerGroup;
00085   if (!tmp) {
00086     tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
00087     sys::MemoryFence();
00088     DefaultTimerGroup = tmp;
00089   }
00090 
00091   return tmp;
00092 }
00093 
00094 //===----------------------------------------------------------------------===//
00095 // Timer Implementation
00096 //===----------------------------------------------------------------------===//
00097 
00098 void Timer::init(StringRef N) {
00099   init(N, *getDefaultTimerGroup());
00100 }
00101 
00102 void Timer::init(StringRef N, TimerGroup &tg) {
00103   assert(!TG && "Timer already initialized");
00104   Name.assign(N.begin(), N.end());
00105   Running = Triggered = false;
00106   TG = &tg;
00107   TG->addTimer(*this);
00108 }
00109 
00110 Timer::~Timer() {
00111   if (!TG) return;  // Never initialized, or already cleared.
00112   TG->removeTimer(*this);
00113 }
00114 
00115 static inline size_t getMemUsage() {
00116   if (!TrackSpace) return 0;
00117   return sys::Process::GetMallocUsage();
00118 }
00119 
00120 TimeRecord TimeRecord::getCurrentTime(bool Start) {
00121   TimeRecord Result;
00122   sys::TimeValue now(0,0), user(0,0), sys(0,0);
00123   
00124   if (Start) {
00125     Result.MemUsed = getMemUsage();
00126     sys::Process::GetTimeUsage(now, user, sys);
00127   } else {
00128     sys::Process::GetTimeUsage(now, user, sys);
00129     Result.MemUsed = getMemUsage();
00130   }
00131 
00132   Result.WallTime   =  now.seconds() +  now.microseconds() / 1000000.0;
00133   Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
00134   Result.SystemTime =  sys.seconds() +  sys.microseconds() / 1000000.0;
00135   return Result;
00136 }
00137 
00138 void Timer::startTimer() {
00139   assert(!Running && "Cannot start a running timer");
00140   Running = Triggered = true;
00141   StartTime = TimeRecord::getCurrentTime(true);
00142 }
00143 
00144 void Timer::stopTimer() {
00145   assert(Running && "Cannot stop a paused timer");
00146   Running = false;
00147   Time += TimeRecord::getCurrentTime(false);
00148   Time -= StartTime;
00149 }
00150 
00151 void Timer::clear() {
00152   Running = Triggered = false;
00153   Time = StartTime = TimeRecord();
00154 }
00155 
00156 static void printVal(double Val, double Total, raw_ostream &OS) {
00157   if (Total < 1e-7)   // Avoid dividing by zero.
00158     OS << "        -----     ";
00159   else
00160     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
00161 }
00162 
00163 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
00164   if (Total.getUserTime())
00165     printVal(getUserTime(), Total.getUserTime(), OS);
00166   if (Total.getSystemTime())
00167     printVal(getSystemTime(), Total.getSystemTime(), OS);
00168   if (Total.getProcessTime())
00169     printVal(getProcessTime(), Total.getProcessTime(), OS);
00170   printVal(getWallTime(), Total.getWallTime(), OS);
00171   
00172   OS << "  ";
00173   
00174   if (Total.getMemUsed())
00175     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
00176 }
00177 
00178 
00179 //===----------------------------------------------------------------------===//
00180 //   NamedRegionTimer Implementation
00181 //===----------------------------------------------------------------------===//
00182 
00183 namespace {
00184 
00185 typedef StringMap<Timer> Name2TimerMap;
00186 
00187 class Name2PairMap {
00188   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
00189 public:
00190   ~Name2PairMap() {
00191     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
00192          I = Map.begin(), E = Map.end(); I != E; ++I)
00193       delete I->second.first;
00194   }
00195   
00196   Timer &get(StringRef Name, StringRef GroupName) {
00197     sys::SmartScopedLock<true> L(*TimerLock);
00198     
00199     std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
00200     
00201     if (!GroupEntry.first)
00202       GroupEntry.first = new TimerGroup(GroupName);
00203     
00204     Timer &T = GroupEntry.second[Name];
00205     if (!T.isInitialized())
00206       T.init(Name, *GroupEntry.first);
00207     return T;
00208   }
00209 };
00210 
00211 }
00212 
00213 static ManagedStatic<Name2TimerMap> NamedTimers;
00214 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
00215 
00216 static Timer &getNamedRegionTimer(StringRef Name) {
00217   sys::SmartScopedLock<true> L(*TimerLock);
00218   
00219   Timer &T = (*NamedTimers)[Name];
00220   if (!T.isInitialized())
00221     T.init(Name);
00222   return T;
00223 }
00224 
00225 NamedRegionTimer::NamedRegionTimer(StringRef Name,
00226                                    bool Enabled)
00227   : TimeRegion(!Enabled ? nullptr : &getNamedRegionTimer(Name)) {}
00228 
00229 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName,
00230                                    bool Enabled)
00231   : TimeRegion(!Enabled ? nullptr : &NamedGroupedTimers->get(Name, GroupName)){}
00232 
00233 //===----------------------------------------------------------------------===//
00234 //   TimerGroup Implementation
00235 //===----------------------------------------------------------------------===//
00236 
00237 /// TimerGroupList - This is the global list of TimerGroups, maintained by the
00238 /// TimerGroup ctor/dtor and is protected by the TimerLock lock.
00239 static TimerGroup *TimerGroupList = nullptr;
00240 
00241 TimerGroup::TimerGroup(StringRef name)
00242   : Name(name.begin(), name.end()), FirstTimer(nullptr) {
00243     
00244   // Add the group to TimerGroupList.
00245   sys::SmartScopedLock<true> L(*TimerLock);
00246   if (TimerGroupList)
00247     TimerGroupList->Prev = &Next;
00248   Next = TimerGroupList;
00249   Prev = &TimerGroupList;
00250   TimerGroupList = this;
00251 }
00252 
00253 TimerGroup::~TimerGroup() {
00254   // If the timer group is destroyed before the timers it owns, accumulate and
00255   // print the timing data.
00256   while (FirstTimer)
00257     removeTimer(*FirstTimer);
00258   
00259   // Remove the group from the TimerGroupList.
00260   sys::SmartScopedLock<true> L(*TimerLock);
00261   *Prev = Next;
00262   if (Next)
00263     Next->Prev = Prev;
00264 }
00265 
00266 
00267 void TimerGroup::removeTimer(Timer &T) {
00268   sys::SmartScopedLock<true> L(*TimerLock);
00269   
00270   // If the timer was started, move its data to TimersToPrint.
00271   if (T.hasTriggered())
00272     TimersToPrint.emplace_back(T.Time, T.Name);
00273 
00274   T.TG = nullptr;
00275   
00276   // Unlink the timer from our list.
00277   *T.Prev = T.Next;
00278   if (T.Next)
00279     T.Next->Prev = T.Prev;
00280   
00281   // Print the report when all timers in this group are destroyed if some of
00282   // them were started.
00283   if (FirstTimer || TimersToPrint.empty())
00284     return;
00285 
00286   std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
00287   PrintQueuedTimers(*OutStream);
00288 }
00289 
00290 void TimerGroup::addTimer(Timer &T) {
00291   sys::SmartScopedLock<true> L(*TimerLock);
00292   
00293   // Add the timer to our list.
00294   if (FirstTimer)
00295     FirstTimer->Prev = &T.Next;
00296   T.Next = FirstTimer;
00297   T.Prev = &FirstTimer;
00298   FirstTimer = &T;
00299 }
00300 
00301 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
00302   // Sort the timers in descending order by amount of time taken.
00303   std::sort(TimersToPrint.begin(), TimersToPrint.end());
00304   
00305   TimeRecord Total;
00306   for (auto &RecordNamePair : TimersToPrint)
00307     Total += RecordNamePair.first;
00308   
00309   // Print out timing header.
00310   OS << "===" << std::string(73, '-') << "===\n";
00311   // Figure out how many spaces to indent TimerGroup name.
00312   unsigned Padding = (80-Name.length())/2;
00313   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
00314   OS.indent(Padding) << Name << '\n';
00315   OS << "===" << std::string(73, '-') << "===\n";
00316   
00317   // If this is not an collection of ungrouped times, print the total time.
00318   // Ungrouped timers don't really make sense to add up.  We still print the
00319   // TOTAL line to make the percentages make sense.
00320   if (this != DefaultTimerGroup)
00321     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
00322                  Total.getProcessTime(), Total.getWallTime());
00323   OS << '\n';
00324   
00325   if (Total.getUserTime())
00326     OS << "   ---User Time---";
00327   if (Total.getSystemTime())
00328     OS << "   --System Time--";
00329   if (Total.getProcessTime())
00330     OS << "   --User+System--";
00331   OS << "   ---Wall Time---";
00332   if (Total.getMemUsed())
00333     OS << "  ---Mem---";
00334   OS << "  --- Name ---\n";
00335   
00336   // Loop through all of the timing data, printing it out.
00337   for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
00338     const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
00339     Entry.first.print(Total, OS);
00340     OS << Entry.second << '\n';
00341   }
00342   
00343   Total.print(Total, OS);
00344   OS << "Total\n\n";
00345   OS.flush();
00346   
00347   TimersToPrint.clear();
00348 }
00349 
00350 /// print - Print any started timers in this group and zero them.
00351 void TimerGroup::print(raw_ostream &OS) {
00352   sys::SmartScopedLock<true> L(*TimerLock);
00353 
00354   // See if any of our timers were started, if so add them to TimersToPrint and
00355   // reset them.
00356   for (Timer *T = FirstTimer; T; T = T->Next) {
00357     if (!T->hasTriggered()) continue;
00358     TimersToPrint.emplace_back(T->Time, T->Name);
00359     
00360     // Clear out the time.
00361     T->clear();
00362   }
00363 
00364   // If any timers were started, print the group.
00365   if (!TimersToPrint.empty())
00366     PrintQueuedTimers(OS);
00367 }
00368 
00369 /// printAll - This static method prints all timers and clears them all out.
00370 void TimerGroup::printAll(raw_ostream &OS) {
00371   sys::SmartScopedLock<true> L(*TimerLock);
00372 
00373   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
00374     TG->print(OS);
00375 }