Timer.cpp revision 9f9f6d19dd67926446fb89a7b2dc0bda6353645b
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/System/Mutex.h" 21#include "llvm/System/Process.h" 22#include "llvm/ADT/StringMap.h" 23using namespace llvm; 24 25// GetLibSupportInfoOutputFile - Return a file stream to print our output on. 26namespace llvm { extern raw_ostream *GetLibSupportInfoOutputFile(); } 27 28// getLibSupportInfoOutputFilename - This ugly hack is brought to you courtesy 29// of constructor/destructor ordering being unspecified by C++. Basically the 30// problem is that a Statistic object gets destroyed, which ends up calling 31// 'GetLibSupportInfoOutputFile()' (below), which calls this function. 32// LibSupportInfoOutputFilename used to be a global variable, but sometimes it 33// would get destroyed before the Statistic, causing havoc to ensue. We "fix" 34// this by creating the string the first time it is needed and never destroying 35// it. 36static ManagedStatic<std::string> LibSupportInfoOutputFilename; 37static std::string &getLibSupportInfoOutputFilename() { 38 return *LibSupportInfoOutputFilename; 39} 40 41static ManagedStatic<sys::SmartMutex<true> > TimerLock; 42 43namespace { 44 static cl::opt<bool> 45 TrackSpace("track-memory", cl::desc("Enable -time-passes memory " 46 "tracking (this may be slow)"), 47 cl::Hidden); 48 49 static cl::opt<std::string, true> 50 InfoOutputFilename("info-output-file", cl::value_desc("filename"), 51 cl::desc("File to append -stats and -timer output to"), 52 cl::Hidden, cl::location(getLibSupportInfoOutputFilename())); 53} 54 55// GetLibSupportInfoOutputFile - Return a file stream to print our output on. 56raw_ostream *llvm::GetLibSupportInfoOutputFile() { 57 std::string &LibSupportInfoOutputFilename = getLibSupportInfoOutputFilename(); 58 if (LibSupportInfoOutputFilename.empty()) 59 return &errs(); 60 if (LibSupportInfoOutputFilename == "-") 61 return &outs(); 62 63 std::string Error; 64 raw_ostream *Result = new raw_fd_ostream(LibSupportInfoOutputFilename.c_str(), 65 Error, raw_fd_ostream::F_Append); 66 if (Error.empty()) 67 return Result; 68 69 errs() << "Error opening info-output-file '" 70 << LibSupportInfoOutputFilename << " for appending!\n"; 71 delete Result; 72 return &errs(); 73} 74 75 76static TimerGroup *DefaultTimerGroup = 0; 77static TimerGroup *getDefaultTimerGroup() { 78 TimerGroup *tmp = DefaultTimerGroup; 79 sys::MemoryFence(); 80 if (tmp) return tmp; 81 82 llvm_acquire_global_lock(); 83 tmp = DefaultTimerGroup; 84 if (!tmp) { 85 tmp = new TimerGroup("Miscellaneous Ungrouped Timers"); 86 sys::MemoryFence(); 87 DefaultTimerGroup = tmp; 88 } 89 llvm_release_global_lock(); 90 91 return tmp; 92} 93 94//===----------------------------------------------------------------------===// 95// Timer Implementation 96//===----------------------------------------------------------------------===// 97 98void Timer::init(const std::string &N) { 99 assert(TG == 0 && "Timer already initialized"); 100 Name = N; 101 Started = false; 102 TG = getDefaultTimerGroup(); 103 TG->addTimer(*this); 104} 105 106void Timer::init(const std::string &N, TimerGroup &tg) { 107 assert(TG == 0 && "Timer already initialized"); 108 Name = N; 109 Started = false; 110 TG = &tg; 111 TG->addTimer(*this); 112} 113 114Timer::~Timer() { 115 if (!TG) return; // Never initialized. 116 TG->removeTimer(*this); 117} 118 119static inline size_t getMemUsage() { 120 if (TrackSpace) 121 return sys::Process::GetMallocUsage(); 122 return 0; 123} 124 125TimeRecord TimeRecord::getCurrentTime(bool Start) { 126 TimeRecord Result; 127 128 sys::TimeValue now(0,0); 129 sys::TimeValue user(0,0); 130 sys::TimeValue sys(0,0); 131 132 ssize_t MemUsed = 0; 133 if (Start) { 134 MemUsed = getMemUsage(); 135 sys::Process::GetTimeUsage(now, user, sys); 136 } else { 137 sys::Process::GetTimeUsage(now, user, sys); 138 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 Result.MemUsed = MemUsed; 145 return Result; 146} 147 148static ManagedStatic<std::vector<Timer*> > ActiveTimers; 149 150void Timer::startTimer() { 151 Started = true; 152 ActiveTimers->push_back(this); 153 Time -= TimeRecord::getCurrentTime(true); 154} 155 156void Timer::stopTimer() { 157 Time += TimeRecord::getCurrentTime(false); 158 159 if (ActiveTimers->back() == this) { 160 ActiveTimers->pop_back(); 161 } else { 162 std::vector<Timer*>::iterator I = 163 std::find(ActiveTimers->begin(), ActiveTimers->end(), this); 164 assert(I != ActiveTimers->end() && "stop but no startTimer?"); 165 ActiveTimers->erase(I); 166 } 167} 168 169static void printVal(double Val, double Total, raw_ostream &OS) { 170 if (Total < 1e-7) // Avoid dividing by zero. 171 OS << " ----- "; 172 else { 173 OS << " " << format("%7.4f", Val) << " ("; 174 OS << format("%5.1f", Val*100/Total) << "%)"; 175 } 176} 177 178void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const { 179 if (Total.getUserTime()) 180 printVal(getUserTime(), Total.getUserTime(), OS); 181 if (Total.getSystemTime()) 182 printVal(getSystemTime(), Total.getSystemTime(), OS); 183 if (Total.getProcessTime()) 184 printVal(getProcessTime(), Total.getProcessTime(), OS); 185 printVal(getWallTime(), Total.getWallTime(), OS); 186 187 OS << " "; 188 189 if (Total.getMemUsed()) 190 OS << format("%9lld", (long long)getMemUsed()) << " "; 191} 192 193 194//===----------------------------------------------------------------------===// 195// NamedRegionTimer Implementation 196//===----------------------------------------------------------------------===// 197 198typedef StringMap<Timer> Name2TimerMap; 199typedef StringMap<std::pair<TimerGroup, Name2TimerMap> > Name2PairMap; 200 201static ManagedStatic<Name2TimerMap> NamedTimers; 202static ManagedStatic<Name2PairMap> NamedGroupedTimers; 203 204static Timer &getNamedRegionTimer(const std::string &Name) { 205 sys::SmartScopedLock<true> L(*TimerLock); 206 207 Timer &T = (*NamedTimers)[Name]; 208 if (!T.isInitialized()) 209 T.init(Name); 210 return T; 211} 212 213static Timer &getNamedRegionTimer(const std::string &Name, 214 const std::string &GroupName) { 215 sys::SmartScopedLock<true> L(*TimerLock); 216 217 std::pair<TimerGroup, Name2TimerMap> &GroupEntry = 218 (*NamedGroupedTimers)[GroupName]; 219 220 if (GroupEntry.second.empty()) 221 GroupEntry.first.setName(GroupName); 222 223 Timer &T = GroupEntry.second[Name]; 224 if (!T.isInitialized()) 225 T.init(Name); 226 return T; 227} 228 229NamedRegionTimer::NamedRegionTimer(const std::string &Name) 230 : TimeRegion(getNamedRegionTimer(Name)) {} 231 232NamedRegionTimer::NamedRegionTimer(const std::string &Name, 233 const std::string &GroupName) 234 : TimeRegion(getNamedRegionTimer(Name, GroupName)) {} 235 236//===----------------------------------------------------------------------===// 237// TimerGroup Implementation 238//===----------------------------------------------------------------------===// 239 240TimerGroup::~TimerGroup() { 241 // If the timer group is destroyed before the timers it owns, accumulate and 242 // print the timing data. 243 while (FirstTimer != 0) 244 removeTimer(*FirstTimer); 245} 246 247 248void TimerGroup::removeTimer(Timer &T) { 249 sys::SmartScopedLock<true> L(*TimerLock); 250 251 // If the timer was started, move its data to TimersToPrint. 252 if (T.Started) 253 TimersToPrint.push_back(std::make_pair(T.Time, T.Name)); 254 255 T.TG = 0; 256 257 // Unlink the timer from our list. 258 *T.Prev = T.Next; 259 if (T.Next) 260 T.Next->Prev = T.Prev; 261 262 // Print the report when all timers in this group are destroyed if some of 263 // them were started. 264 if (FirstTimer != 0 || TimersToPrint.empty()) 265 return; 266 267 raw_ostream *OutStream = GetLibSupportInfoOutputFile(); 268 269 PrintQueuedTimers(*OutStream); 270 271 if (OutStream != &errs() && OutStream != &outs()) 272 delete OutStream; // Close the file. 273} 274 275void TimerGroup::addTimer(Timer &T) { 276 sys::SmartScopedLock<true> L(*TimerLock); 277 278 // Add the timer to our list. 279 if (FirstTimer) 280 FirstTimer->Prev = &T.Next; 281 T.Next = FirstTimer; 282 T.Prev = &FirstTimer; 283 FirstTimer = &T; 284} 285 286void TimerGroup::PrintQueuedTimers(raw_ostream &OS) { 287 // Sort the timers in descending order by amount of time taken. 288 std::sort(TimersToPrint.begin(), TimersToPrint.end()); 289 290 TimeRecord Total; 291 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) 292 Total += TimersToPrint[i].first; 293 294 // Print out timing header. 295 OS << "===" << std::string(73, '-') << "===\n"; 296 // Figure out how many spaces to indent TimerGroup name. 297 unsigned Padding = (80-Name.length())/2; 298 if (Padding > 80) Padding = 0; // Don't allow "negative" numbers 299 OS.indent(Padding) << Name << '\n'; 300 OS << "===" << std::string(73, '-') << "===\n"; 301 302 // If this is not an collection of ungrouped times, print the total time. 303 // Ungrouped timers don't really make sense to add up. We still print the 304 // TOTAL line to make the percentages make sense. 305 if (this != DefaultTimerGroup) { 306 OS << " Total Execution Time: "; 307 OS << format("%5.4f", Total.getProcessTime()) << " seconds ("; 308 OS << format("%5.4f", Total.getWallTime()) << " wall clock)\n"; 309 } 310 OS << '\n'; 311 312 if (Total.getUserTime()) 313 OS << " ---User Time---"; 314 if (Total.getSystemTime()) 315 OS << " --System Time--"; 316 if (Total.getProcessTime()) 317 OS << " --User+System--"; 318 OS << " ---Wall Time---"; 319 if (Total.getMemUsed()) 320 OS << " ---Mem---"; 321 OS << " --- Name ---\n"; 322 323 // Loop through all of the timing data, printing it out. 324 for (unsigned i = 0, e = TimersToPrint.size(); i != e; ++i) { 325 const std::pair<TimeRecord, std::string> &Entry = TimersToPrint[e-i-1]; 326 Entry.first.print(Total, OS); 327 OS << Entry.second << '\n'; 328 } 329 330 Total.print(Total, OS); 331 OS << "Total\n\n"; 332 OS.flush(); 333 334 TimersToPrint.clear(); 335} 336 337