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

Generated by: LCOV version 1.13