LCOV - code coverage report
Current view: top level - lib/Support - Timer.cpp (source / functions) Hit Total Coverage
Test: llvm-toolchain.info Lines: 173 207 83.6 %
Date: 2017-09-14 15:23:50 Functions: 26 28 92.9 %
Legend: Lines: hit not hit

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

Generated by: LCOV version 1.13