Home | History | Annotate | Download | only in Support
      1 //===-- Timer.cpp - Interval Timing Support -------------------------------===//
      2 //
      3 //                     The LLVM Compiler Infrastructure
      4 //
      5 // This file is distributed under the University of Illinois Open Source
      6 // License. See LICENSE.TXT for details.
      7 //
      8 //===----------------------------------------------------------------------===//
      9 //
     10 // Interval Timing implementation.
     11 //
     12 //===----------------------------------------------------------------------===//
     13 
     14 #include "llvm/Support/Timer.h"
     15 #include "llvm/Support/CommandLine.h"
     16 #include "llvm/Support/Debug.h"
     17 #include "llvm/Support/ManagedStatic.h"
     18 #include "llvm/Support/raw_ostream.h"
     19 #include "llvm/Support/Format.h"
     20 #include "llvm/Support/Mutex.h"
     21 #include "llvm/Support/Process.h"
     22 #include "llvm/ADT/OwningPtr.h"
     23 #include "llvm/ADT/StringMap.h"
     24 using namespace llvm;
     25 
     26 // CreateInfoOutputFile - Return a file stream to print our output on.
     27 namespace llvm { extern raw_ostream *CreateInfoOutputFile(); }
     28 
     29 // getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy
     30 // of constructor/destructor ordering being unspecified by C++.  Basically the
     31 // problem is that a Statistic object gets destroyed, which ends up calling
     32 // 'GetLibSupportInfoOutputFile()' (below), which calls this function.
     33 // LibSupportInfoOutputFilename used to be a global variable, but sometimes it
     34 // would get destroyed before the Statistic, causing havoc to ensue.  We "fix"
     35 // this by creating the string the first time it is needed and never destroying
     36 // it.
     37 static ManagedStatic<std::string> LibSupportInfoOutputFilename;
     38 static std::string &getLibSupportInfoOutputFilename() {
     39   return *LibSupportInfoOutputFilename;
     40 }
     41 
     42 static ManagedStatic<sys::SmartMutex<true> > TimerLock;
     43 
     44 namespace {
     45   static cl::opt<bool>
     46   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
     47                                       "tracking (this may be slow)"),
     48              cl::Hidden);
     49 
     50   static cl::opt<std::string, true>
     51   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
     52                      cl::desc("File to append -stats and -timer output to"),
     53                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
     54 }
     55 
     56 // CreateInfoOutputFile - Return a file stream to print our output on.
     57 raw_ostream *llvm::CreateInfoOutputFile() {
     58   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
     59   if (OutputFilename.empty())
     60     return new raw_fd_ostream(2, false); // stderr.
     61   if (OutputFilename == "-")
     62     return new raw_fd_ostream(1, false); // stdout.
     63 
     64   // Append mode is used because the info output file is opened and closed
     65   // each time -stats or -time-passes wants to print output to it. To
     66   // compensate for this, the test-suite Makefiles have code to delete the
     67   // info output file before running commands which write to it.
     68   std::string Error;
     69   raw_ostream *Result = new raw_fd_ostream(OutputFilename.c_str(),
     70                                            Error, raw_fd_ostream::F_Append);
     71   if (Error.empty())
     72     return Result;
     73 
     74   errs() << "Error opening info-output-file '"
     75     << OutputFilename << " for appending!\n";
     76   delete Result;
     77   return new raw_fd_ostream(2, false); // stderr.
     78 }
     79 
     80 
     81 static TimerGroup *DefaultTimerGroup = 0;
     82 static TimerGroup *getDefaultTimerGroup() {
     83   TimerGroup *tmp = DefaultTimerGroup;
     84   sys::MemoryFence();
     85   if (tmp) return tmp;
     86 
     87   llvm_acquire_global_lock();
     88   tmp = DefaultTimerGroup;
     89   if (!tmp) {
     90     tmp = new TimerGroup("Miscellaneous Ungrouped Timers");
     91     sys::MemoryFence();
     92     DefaultTimerGroup = tmp;
     93   }
     94   llvm_release_global_lock();
     95 
     96   return tmp;
     97 }
     98 
     99 //===----------------------------------------------------------------------===//
    100 // Timer Implementation
    101 //===----------------------------------------------------------------------===//
    102 
    103 void Timer::init(StringRef N) {
    104   assert(TG == 0 && "Timer already initialized");
    105   Name.assign(N.begin(), N.end());
    106   Started = false;
    107   TG = getDefaultTimerGroup();
    108   TG->addTimer(*this);
    109 }
    110 
    111 void Timer::init(StringRef N, TimerGroup &tg) {
    112   assert(TG == 0 && "Timer already initialized");
    113   Name.assign(N.begin(), N.end());
    114   Started = false;
    115   TG = &tg;
    116   TG->addTimer(*this);
    117 }
    118 
    119 Timer::~Timer() {
    120   if (!TG) return;  // Never initialized, or already cleared.
    121   TG->removeTimer(*this);
    122 }
    123 
    124 static inline size_t getMemUsage() {
    125   if (!TrackSpace) return 0;
    126   return sys::Process::GetMallocUsage();
    127 }
    128 
    129 TimeRecord TimeRecord::getCurrentTime(bool Start) {
    130   TimeRecord Result;
    131   sys::TimeValue now(0,0), user(0,0), sys(0,0);
    132 
    133   if (Start) {
    134     Result.MemUsed = getMemUsage();
    135     sys::Process::GetTimeUsage(now, user, sys);
    136   } else {
    137     sys::Process::GetTimeUsage(now, user, sys);
    138     Result.MemUsed = getMemUsage();
    139   }
    140 
    141   Result.WallTime   =  now.seconds() +  now.microseconds() / 1000000.0;
    142   Result.UserTime   = user.seconds() + user.microseconds() / 1000000.0;
    143   Result.SystemTime =  sys.seconds() +  sys.microseconds() / 1000000.0;
    144   return Result;
    145 }
    146 
    147 static ManagedStatic<std::vector<Timer*> > ActiveTimers;
    148 
    149 void Timer::startTimer() {
    150   Started = true;
    151   ActiveTimers->push_back(this);
    152   Time -= TimeRecord::getCurrentTime(true);
    153 }
    154 
    155 void Timer::stopTimer() {
    156   Time += TimeRecord::getCurrentTime(false);
    157 
    158   if (ActiveTimers->back() == this) {
    159     ActiveTimers->pop_back();
    160   } else {
    161     std::vector<Timer*>::iterator I =
    162       std::find(ActiveTimers->begin(), ActiveTimers->end(), this);
    163     assert(I != ActiveTimers->end() && "stop but no startTimer?");
    164     ActiveTimers->erase(I);
    165   }
    166 }
    167 
    168 static void printVal(double Val, double Total, raw_ostream &OS) {
    169   if (Total < 1e-7)   // Avoid dividing by zero.
    170     OS << "        -----     ";
    171   else
    172     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
    173 }
    174 
    175 void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
    176   if (Total.getUserTime())
    177     printVal(getUserTime(), Total.getUserTime(), OS);
    178   if (Total.getSystemTime())
    179     printVal(getSystemTime(), Total.getSystemTime(), OS);
    180   if (Total.getProcessTime())
    181     printVal(getProcessTime(), Total.getProcessTime(), OS);
    182   printVal(getWallTime(), Total.getWallTime(), OS);
    183 
    184   OS << "  ";
    185 
    186   if (Total.getMemUsed())
    187     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
    188 }
    189 
    190 
    191 //===----------------------------------------------------------------------===//
    192 //   NamedRegionTimer Implementation
    193 //===----------------------------------------------------------------------===//
    194 
    195 namespace {
    196 
    197 typedef StringMap<Timer> Name2TimerMap;
    198 
    199 class Name2PairMap {
    200   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
    201 public:
    202   ~Name2PairMap() {
    203     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
    204          I = Map.begin(), E = Map.end(); I != E; ++I)
    205       delete I->second.first;
    206   }
    207 
    208   Timer &get(StringRef Name, StringRef GroupName) {
    209     sys::SmartScopedLock<true> L(*TimerLock);
    210 
    211     std::pair<TimerGroup*, Name2TimerMap> &GroupEntry = Map[GroupName];
    212 
    213     if (!GroupEntry.first)
    214       GroupEntry.first = new TimerGroup(GroupName);
    215 
    216     Timer &T = GroupEntry.second[Name];
    217     if (!T.isInitialized())
    218       T.init(Name, *GroupEntry.first);
    219     return T;
    220   }
    221 };
    222 
    223 }
    224 
    225 static ManagedStatic<Name2TimerMap> NamedTimers;
    226 static ManagedStatic<Name2PairMap> NamedGroupedTimers;
    227 
    228 static Timer &getNamedRegionTimer(StringRef Name) {
    229   sys::SmartScopedLock<true> L(*TimerLock);
    230 
    231   Timer &T = (*NamedTimers)[Name];
    232   if (!T.isInitialized())
    233     T.init(Name);
    234   return T;
    235 }
    236 
    237 NamedRegionTimer::NamedRegionTimer(StringRef Name,
    238                                    bool Enabled)
    239   : TimeRegion(!Enabled ? 0 : &getNamedRegionTimer(Name)) {}
    240 
    241 NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef GroupName,
    242                                    bool Enabled)
    243   : TimeRegion(!Enabled ? 0 : &NamedGroupedTimers->get(Name, GroupName)) {}
    244 
    245 //===----------------------------------------------------------------------===//
    246 //   TimerGroup Implementation
    247 //===----------------------------------------------------------------------===//
    248 
    249 /// TimerGroupList - This is the global list of TimerGroups, maintained by the
    250 /// TimerGroup ctor/dtor and is protected by the TimerLock lock.
    251 static TimerGroup *TimerGroupList = 0;
    252 
    253 TimerGroup::TimerGroup(StringRef name)
    254   : Name(name.begin(), name.end()), FirstTimer(0) {
    255 
    256   // Add the group to TimerGroupList.
    257   sys::SmartScopedLock<true> L(*TimerLock);
    258   if (TimerGroupList)
    259     TimerGroupList->Prev = &Next;
    260   Next = TimerGroupList;
    261   Prev = &TimerGroupList;
    262   TimerGroupList = this;
    263 }
    264 
    265 TimerGroup::~TimerGroup() {
    266   // If the timer group is destroyed before the timers it owns, accumulate and
    267   // print the timing data.
    268   while (FirstTimer != 0)
    269     removeTimer(*FirstTimer);
    270 
    271   // Remove the group from the TimerGroupList.
    272   sys::SmartScopedLock<true> L(*TimerLock);
    273   *Prev = Next;
    274   if (Next)
    275     Next->Prev = Prev;
    276 }
    277 
    278 
    279 void TimerGroup::removeTimer(Timer &T) {
    280   sys::SmartScopedLock<true> L(*TimerLock);
    281 
    282   // If the timer was started, move its data to TimersToPrint.
    283   if (T.Started)
    284     TimersToPrint.push_back(std::make_pair(T.Time, T.Name));
    285 
    286   T.TG = 0;
    287 
    288   // Unlink the timer from our list.
    289   *T.Prev = T.Next;
    290   if (T.Next)
    291     T.Next->Prev = T.Prev;
    292 
    293   // Print the report when all timers in this group are destroyed if some of
    294   // them were started.
    295   if (FirstTimer != 0 || TimersToPrint.empty())
    296     return;
    297 
    298   raw_ostream *OutStream = CreateInfoOutputFile();
    299   PrintQueuedTimers(*OutStream);
    300   delete OutStream;   // Close the file.
    301 }
    302 
    303 void TimerGroup::addTimer(Timer &T) {
    304   sys::SmartScopedLock<true> L(*TimerLock);
    305 
    306   // Add the timer to our list.
    307   if (FirstTimer)
    308     FirstTimer->Prev = &T.Next;
    309   T.Next = FirstTimer;
    310   T.Prev = &FirstTimer;
    311   FirstTimer = &T;
    312 }
    313 
    314 void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
    315   // Sort the timers in descending order by amount of time taken.
    316   std::sort(TimersToPrint.begin(), TimersToPrint.end());
    317 
    318   TimeRecord Total;
    319   for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i)
    320     Total += TimersToPrint[i].first;
    321 
    322   // Print out timing header.
    323   OS << "===" << std::string(73, '-') << "===\n";
    324   // Figure out how many spaces to indent TimerGroup name.
    325   unsigned Padding = (80-Name.length())/2;
    326   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
    327   OS.indent(Padding) << Name << '\n';
    328   OS << "===" << std::string(73, '-') << "===\n";
    329 
    330   // If this is not an collection of ungrouped times, print the total time.
    331   // Ungrouped timers don't really make sense to add up.  We still print the
    332   // TOTAL line to make the percentages make sense.
    333   if (this != DefaultTimerGroup)
    334     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
    335                  Total.getProcessTime(), Total.getWallTime());
    336   OS << '\n';
    337 
    338   if (Total.getUserTime())
    339     OS << "   ---User Time---";
    340   if (Total.getSystemTime())
    341     OS << "   --System Time--";
    342   if (Total.getProcessTime())
    343     OS << "   --User+System--";
    344   OS << "   ---Wall Time---";
    345   if (Total.getMemUsed())
    346     OS << "  ---Mem---";
    347   OS << "  --- Name ---\n";
    348 
    349   // Loop through all of the timing data, printing it out.
    350   for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) {
    351     const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1];
    352     Entry.first.print(Total, OS);
    353     OS << Entry.second << '\n';
    354   }
    355 
    356   Total.print(Total, OS);
    357   OS << "Total\n\n";
    358   OS.flush();
    359 
    360   TimersToPrint.clear();
    361 }
    362 
    363 /// print - Print any started timers in this group and zero them.
    364 void TimerGroup::print(raw_ostream &OS) {
    365   sys::SmartScopedLock<true> L(*TimerLock);
    366 
    367   // See if any of our timers were started, if so add them to TimersToPrint and
    368   // reset them.
    369   for (Timer *T = FirstTimer; T; T = T->Next) {
    370     if (!T->Started) continue;
    371     TimersToPrint.push_back(std::make_pair(T->Time, T->Name));
    372 
    373     // Clear out the time.
    374     T->Started = 0;
    375     T->Time = TimeRecord();
    376   }
    377 
    378   // If any timers were started, print the group.
    379   if (!TimersToPrint.empty())
    380     PrintQueuedTimers(OS);
    381 }
    382 
    383 /// printAll - This static method prints all timers and clears them all out.
    384 void TimerGroup::printAll(raw_ostream &OS) {
    385   sys::SmartScopedLock<true> L(*TimerLock);
    386 
    387   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
    388     TG->print(OS);
    389 }
    390