LCOV - code coverage report
Current view: top level - lib/Support - Timer.cpp (source / functions) Hit Total Coverage
Test: llvm-toolchain.info Lines: 161 197 81.7 %
Date: 2018-02-23 15:42:53 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       81910 :   return *LibSupportInfoOutputFilename;
      37             : }
      38             : 
      39             : static ManagedStatic<sys::SmartMutex<true> > TimerLock;
      40             : 
      41             : namespace {
      42             :   static cl::opt<bool>
      43      163758 :   TrackSpace("track-memory", cl::desc("Enable -time-passes memory "
      44             :                                       "tracking (this may be slow)"),
      45      245637 :              cl::Hidden);
      46             : 
      47             :   static cl::opt<std::string, true>
      48      163758 :   InfoOutputFilename("info-output-file", cl::value_desc("filename"),
      49       81879 :                      cl::desc("File to append -stats and -timer output to"),
      50      245637 :                    cl::Hidden, cl::location(getLibSupportInfoOutputFilename()));
      51             : }
      52             : 
      53          31 : std::unique_ptr<raw_fd_ostream> llvm::CreateInfoOutputFile() {
      54             :   const std::string &OutputFilename = getLibSupportInfoOutputFilename();
      55          31 :   if (OutputFilename.empty())
      56          31 :     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             :   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        8221 :   static void *call() {
      78        8221 :     return new TimerGroup("misc", "Miscellaneous Ungrouped Timers");
      79             :   }
      80             : };
      81             : } // namespace
      82             : static ManagedStatic<TimerGroup, CreateDefaultTimerGroup> DefaultTimerGroup;
      83       16382 : static TimerGroup *getDefaultTimerGroup() { return &*DefaultTimerGroup; }
      84             : 
      85             : //===----------------------------------------------------------------------===//
      86             : // Timer Implementation
      87             : //===----------------------------------------------------------------------===//
      88             : 
      89       16333 : void Timer::init(StringRef Name, StringRef Description) {
      90       16333 :   init(Name, Description, *getDefaultTimerGroup());
      91       16333 : }
      92             : 
      93       17347 : void Timer::init(StringRef Name, StringRef Description, TimerGroup &tg) {
      94             :   assert(!TG && "Timer already initialized");
      95       17347 :   this->Name.assign(Name.begin(), Name.end());
      96       17347 :   this->Description.assign(Description.begin(), Description.end());
      97       17347 :   Running = Triggered = false;
      98       17347 :   TG = &tg;
      99       17347 :   TG->addTimer(*this);
     100       17347 : }
     101             : 
     102       36670 : Timer::~Timer() {
     103       19326 :   if (!TG) return;  // Never initialized, or already cleared.
     104       17344 :   TG->removeTimer(*this);
     105       19326 : }
     106             : 
     107             : static inline size_t getMemUsage() {
     108        4560 :   if (!TrackSpace) return 0;
     109           0 :   return sys::Process::GetMallocUsage();
     110             : }
     111             : 
     112        4560 : TimeRecord TimeRecord::getCurrentTime(bool Start) {
     113             :   using Seconds = std::chrono::duration<double, std::ratio<1>>;
     114             :   TimeRecord Result;
     115        4560 :   sys::TimePoint<> now;
     116             :   std::chrono::nanoseconds user, sys;
     117             : 
     118        4560 :   if (Start) {
     119        2307 :     Result.MemUsed = getMemUsage();
     120        2307 :     sys::Process::GetTimeUsage(now, user, sys);
     121             :   } else {
     122        2253 :     sys::Process::GetTimeUsage(now, user, sys);
     123        2253 :     Result.MemUsed = getMemUsage();
     124             :   }
     125             : 
     126        4560 :   Result.WallTime = Seconds(now.time_since_epoch()).count();
     127        4560 :   Result.UserTime = Seconds(user).count();
     128        4560 :   Result.SystemTime = Seconds(sys).count();
     129        4560 :   return Result;
     130             : }
     131             : 
     132        2253 : void Timer::startTimer() {
     133             :   assert(!Running && "Cannot start a running timer");
     134        2253 :   Running = Triggered = true;
     135        2253 :   StartTime = TimeRecord::getCurrentTime(true);
     136        2253 : }
     137             : 
     138        2253 : void Timer::stopTimer() {
     139             :   assert(Running && "Cannot stop a paused timer");
     140        2253 :   Running = false;
     141        4506 :   Time += TimeRecord::getCurrentTime(false);
     142             :   Time -= StartTime;
     143        2253 : }
     144             : 
     145           1 : void Timer::clear() {
     146           1 :   Running = Triggered = false;
     147           1 :   Time = StartTime = TimeRecord();
     148           1 : }
     149             : 
     150        4268 : static void printVal(double Val, double Total, raw_ostream &OS) {
     151        4268 :   if (Total < 1e-7)   // Avoid dividing by zero.
     152           0 :     OS << "        -----     ";
     153             :   else
     154        8536 :     OS << format("  %7.4f (%5.1f%%)", Val, Val*100/Total);
     155        4268 : }
     156             : 
     157        2092 : void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
     158        2092 :   if (Total.getUserTime())
     159        1022 :     printVal(getUserTime(), Total.getUserTime(), OS);
     160        2092 :   if (Total.getSystemTime())
     161         102 :     printVal(getSystemTime(), Total.getSystemTime(), OS);
     162        4184 :   if (Total.getProcessTime())
     163        2104 :     printVal(getProcessTime(), Total.getProcessTime(), OS);
     164        2092 :   printVal(getWallTime(), Total.getWallTime(), OS);
     165             : 
     166        2092 :   OS << "  ";
     167             : 
     168        2092 :   if (Total.getMemUsed())
     169           0 :     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
     170        2092 : }
     171             : 
     172             : 
     173             : //===----------------------------------------------------------------------===//
     174             : //   NamedRegionTimer Implementation
     175             : //===----------------------------------------------------------------------===//
     176             : 
     177             : namespace {
     178             : 
     179             : typedef StringMap<Timer> Name2TimerMap;
     180             : 
     181             : class Name2PairMap {
     182             :   StringMap<std::pair<TimerGroup*, Name2TimerMap> > Map;
     183             : public:
     184          10 :   ~Name2PairMap() {
     185             :     for (StringMap<std::pair<TimerGroup*, Name2TimerMap> >::iterator
     186          10 :          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    11748233 : NamedRegionTimer::NamedRegionTimer(StringRef Name, StringRef Description,
     211             :                                    StringRef GroupName,
     212    11748233 :                                    StringRef GroupDescription, bool Enabled)
     213             :   : TimeRegion(!Enabled ? nullptr
     214             :                  : &NamedGroupedTimers->get(Name, Description, GroupName,
     215    23496466 :                                             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        8243 : TimerGroup::TimerGroup(StringRef Name, StringRef Description)
     226             :   : Name(Name.begin(), Name.end()),
     227       24729 :     Description(Description.begin(), Description.end()) {
     228             :   // Add the group to TimerGroupList.
     229        8243 :   sys::SmartScopedLock<true> L(*TimerLock);
     230        8243 :   if (TimerGroupList)
     231          22 :     TimerGroupList->Prev = &Next;
     232        8243 :   Next = TimerGroupList;
     233        8243 :   Prev = &TimerGroupList;
     234        8243 :   TimerGroupList = this;
     235        8243 : }
     236             : 
     237       24714 : TimerGroup::~TimerGroup() {
     238             :   // If the timer group is destroyed before the timers it owns, accumulate and
     239             :   // print the timing data.
     240        8238 :   while (FirstTimer)
     241           0 :     removeTimer(*FirstTimer);
     242             : 
     243             :   // Remove the group from the TimerGroupList.
     244        8238 :   sys::SmartScopedLock<true> L(*TimerLock);
     245        8238 :   *Prev = Next;
     246        8238 :   if (Next)
     247          14 :     Next->Prev = Prev;
     248        8238 : }
     249             : 
     250             : 
     251       17344 : void TimerGroup::removeTimer(Timer &T) {
     252       17344 :   sys::SmartScopedLock<true> L(*TimerLock);
     253             : 
     254             :   // If the timer was started, move its data to TimersToPrint.
     255       17344 :   if (T.hasTriggered())
     256        1027 :     TimersToPrint.emplace_back(T.Time, T.Name, T.Description);
     257             : 
     258       17344 :   T.TG = nullptr;
     259             : 
     260             :   // Unlink the timer from our list.
     261       17344 :   *T.Prev = T.Next;
     262       17344 :   if (T.Next)
     263        9058 :     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       25594 :   if (FirstTimer || TimersToPrint.empty())
     268             :     return;
     269             : 
     270          62 :   std::unique_ptr<raw_ostream> OutStream = CreateInfoOutputFile();
     271          31 :   PrintQueuedTimers(*OutStream);
     272             : }
     273             : 
     274       17347 : void TimerGroup::addTimer(Timer &T) {
     275       17347 :   sys::SmartScopedLock<true> L(*TimerLock);
     276             : 
     277             :   // Add the timer to our list.
     278       17347 :   if (FirstTimer)
     279        9095 :     FirstTimer->Prev = &T.Next;
     280       17347 :   T.Next = FirstTimer;
     281       17347 :   T.Prev = &FirstTimer;
     282       17347 :   FirstTimer = &T;
     283       17347 : }
     284             : 
     285          49 : void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
     286             :   // Sort the timers in descending order by amount of time taken.
     287             :   std::sort(TimersToPrint.begin(), TimersToPrint.end());
     288             : 
     289             :   TimeRecord Total;
     290        2074 :   for (const PrintRecord &Record : TimersToPrint)
     291             :     Total += Record.Time;
     292             : 
     293             :   // Print out timing header.
     294         147 :   OS << "===" << std::string(73, '-') << "===\n";
     295             :   // Figure out how many spaces to indent TimerGroup name.
     296          49 :   unsigned Padding = (80-Description.length())/2;
     297          49 :   if (Padding > 80) Padding = 0;         // Don't allow "negative" numbers
     298          49 :   OS.indent(Padding) << Description << '\n';
     299         147 :   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          49 :   if (this != getDefaultTimerGroup())
     305          40 :     OS << format("  Total Execution Time: %5.4f seconds (%5.4f wall clock)\n",
     306          40 :                  Total.getProcessTime(), Total.getWallTime());
     307             :   OS << '\n';
     308             : 
     309          49 :   if (Total.getUserTime())
     310          30 :     OS << "   ---User Time---";
     311          49 :   if (Total.getSystemTime())
     312          26 :     OS << "   --System Time--";
     313          98 :   if (Total.getProcessTime())
     314          34 :     OS << "   --User+System--";
     315          49 :   OS << "   ---Wall Time---";
     316          49 :   if (Total.getMemUsed())
     317           0 :     OS << "  ---Mem---";
     318          49 :   OS << "  --- Name ---\n";
     319             : 
     320             :   // Loop through all of the timing data, printing it out.
     321             :   for (const PrintRecord &Record : make_range(TimersToPrint.rbegin(),
     322        2074 :                                               TimersToPrint.rend())) {
     323        2025 :     Record.Time.print(Total, OS);
     324             :     OS << Record.Description << '\n';
     325             :   }
     326             : 
     327          49 :   Total.print(Total, OS);
     328          49 :   OS << "Total\n\n";
     329             :   OS.flush();
     330             : 
     331             :   TimersToPrint.clear();
     332          49 : }
     333             : 
     334        8235 : void TimerGroup::prepareToPrintList() {
     335             :   // See if any of our timers were started, if so add them to TimersToPrint and
     336             :   // reset them.
     337        9233 :   for (Timer *T = FirstTimer; T; T = T->Next) {
     338         998 :     if (!T->hasTriggered()) continue;
     339         998 :     bool WasRunning = T->isRunning();
     340         998 :     if (WasRunning)
     341           0 :       T->stopTimer();
     342             : 
     343         998 :     TimersToPrint.emplace_back(T->Time, T->Name, T->Description);
     344             : 
     345         998 :     if (WasRunning)
     346           0 :       T->startTimer();
     347             :   }
     348        8235 : }
     349             : 
     350        8234 : void TimerGroup::print(raw_ostream &OS) {
     351        8234 :   sys::SmartScopedLock<true> L(*TimerLock);
     352             : 
     353        8234 :   prepareToPrintList();
     354             : 
     355             :   // If any timers were started, print the group.
     356        8234 :   if (!TimersToPrint.empty())
     357          18 :     PrintQueuedTimers(OS);
     358        8234 : }
     359             : 
     360       27234 : void TimerGroup::printAll(raw_ostream &OS) {
     361       27234 :   sys::SmartScopedLock<true> L(*TimerLock);
     362             : 
     363       35468 :   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
     364        8234 :     TG->print(OS);
     365       27234 : }
     366             : 
     367           0 : void TimerGroup::printJSONValue(raw_ostream &OS, const PrintRecord &R,
     368             :                                 const char *suffix, double Value) {
     369             :   assert(yaml::needsQuotes(Name) == yaml::QuotingType::None &&
     370             :          "TimerGroup name needs no quotes");
     371             :   assert(yaml::needsQuotes(R.Name) == yaml::QuotingType::None &&
     372             :          "Timer name needs no quotes");
     373           0 :   OS << "\t\"time." << Name << '.' << R.Name << suffix << "\": " << Value;
     374           0 : }
     375             : 
     376           1 : const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
     377           1 :   prepareToPrintList();
     378           1 :   for (const PrintRecord &R : TimersToPrint) {
     379           0 :     OS << delim;
     380             :     delim = ",\n";
     381             : 
     382             :     const TimeRecord &T = R.Time;
     383           0 :     printJSONValue(OS, R, ".wall", T.getWallTime());
     384           0 :     OS << delim;
     385           0 :     printJSONValue(OS, R, ".user", T.getUserTime());
     386           0 :     OS << delim;
     387           0 :     printJSONValue(OS, R, ".sys", T.getSystemTime());
     388           0 :     if (T.getMemUsed()) {
     389           0 :       OS << delim;
     390           0 :       printJSONValue(OS, R, ".sys", T.getMemUsed());
     391             :     }
     392             :   }
     393             :   TimersToPrint.clear();
     394           1 :   return delim;
     395             : }
     396             : 
     397           1 : const char *TimerGroup::printAllJSONValues(raw_ostream &OS, const char *delim) {
     398           1 :   sys::SmartScopedLock<true> L(*TimerLock);
     399           2 :   for (TimerGroup *TG = TimerGroupList; TG; TG = TG->Next)
     400           1 :     delim = TG->printJSONValues(OS, delim);
     401           1 :   return delim;
     402             : }
     403             : 
     404           5 : void TimerGroup::ConstructTimerLists() {
     405           5 :   (void)*NamedGroupedTimers;
     406      245642 : }

Generated by: LCOV version 1.13