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