//===- subzero/src/IceTimerTree.cpp - Pass timer defs ---------------------===// // // The Subzero Code Generator // // This file is distributed under the University of Illinois Open Source // License. See LICENSE.TXT for details. // //===----------------------------------------------------------------------===// /// /// \file /// \brief Defines the TimerTree class, which tracks flat and cumulative /// execution time collection of call chains. /// //===----------------------------------------------------------------------===// #include "IceTimerTree.h" #include "IceDefs.h" #ifdef __clang__ #pragma clang diagnostic push #pragma clang diagnostic ignored "-Wunused-parameter" #endif // __clang__ #include "llvm/Support/Format.h" #include "llvm/Support/Timer.h" #ifdef __clang__ #pragma clang diagnostic pop #endif // __clang__ namespace Ice { TimerStack::TimerStack(const std::string &Name) : Name(Name), FirstTimestamp(timestamp()), LastTimestamp(FirstTimestamp) { if (!BuildDefs::timers()) return; Nodes.resize(1); // Reserve Nodes[0] for the root node (sentinel). IDs.resize(TT__num); LeafTimes.resize(TT__num); LeafCounts.resize(TT__num); #define STR(s) #s #define X(tag) \ IDs[TT_##tag] = STR(tag); \ IDsIndex[STR(tag)] = TT_##tag; TIMERTREE_TABLE; #undef X #undef STR } // Returns the unique timer ID for the given Name, creating a new ID if needed. TimerIdT TimerStack::getTimerID(const std::string &Name) { if (!BuildDefs::timers()) return 0; if (IDsIndex.find(Name) == IDsIndex.end()) { IDsIndex[Name] = IDs.size(); IDs.push_back(Name); LeafTimes.push_back(decltype(LeafTimes)::value_type()); LeafCounts.push_back(decltype(LeafCounts)::value_type()); } return IDsIndex[Name]; } // Creates a mapping from TimerIdT (leaf) values in the Src timer stack into // TimerIdT values in this timer stack. Creates new entries in this timer stack // as needed. TimerStack::TranslationType TimerStack::translateIDsFrom(const TimerStack &Src) { size_t Size = Src.IDs.size(); TranslationType Mapping(Size); for (TimerIdT i = 0; i < Size; ++i) { Mapping[i] = getTimerID(Src.IDs[i]); } return Mapping; } // Merges two timer stacks, by combining and summing corresponding entries. // This timer stack is updated from Src. void TimerStack::mergeFrom(const TimerStack &Src) { if (!BuildDefs::timers()) return; TranslationType Mapping = translateIDsFrom(Src); TTindex SrcIndex = 0; for (const TimerTreeNode &SrcNode : Src.Nodes) { // The first node is reserved as a sentinel, so avoid it. if (SrcIndex > 0) { // Find the full path to the Src node, translated to path components // corresponding to this timer stack. PathType MyPath = Src.getPath(SrcIndex, Mapping); // Find a node in this timer stack corresponding to the given path, // creating new interior nodes as necessary. TTindex MyIndex = findPath(MyPath); Nodes[MyIndex].Time += SrcNode.Time; Nodes[MyIndex].UpdateCount += SrcNode.UpdateCount; } ++SrcIndex; } for (TimerIdT i = 0; i < Src.LeafTimes.size(); ++i) { LeafTimes[Mapping[i]] += Src.LeafTimes[i]; LeafCounts[Mapping[i]] += Src.LeafCounts[i]; } StateChangeCount += Src.StateChangeCount; } // Constructs a path consisting of the sequence of leaf values leading to a // given node, with the Mapping translation applied to the leaf values. The // path ends up being in "reverse" order, i.e. from leaf to root. TimerStack::PathType TimerStack::getPath(TTindex Index, const TranslationType &Mapping) const { PathType Path; while (Index) { Path.push_back(Mapping[Nodes[Index].Interior]); assert(Nodes[Index].Parent < Index); Index = Nodes[Index].Parent; } return Path; } // Given a parent node and a leaf ID, returns the index of the parent's child // ID, creating a new node for the child as necessary. TimerStack::TTindex TimerStack::getChildIndex(TimerStack::TTindex Parent, TimerIdT ID) { if (Nodes[Parent].Children.size() <= ID) Nodes[Parent].Children.resize(ID + 1); if (Nodes[Parent].Children[ID] == 0) { TTindex Size = Nodes.size(); Nodes[Parent].Children[ID] = Size; Nodes.resize(Size + 1); Nodes[Size].Parent = Parent; Nodes[Size].Interior = ID; } return Nodes[Parent].Children[ID]; } // Finds a node in the timer stack corresponding to the given path, creating // new interior nodes as necessary. TimerStack::TTindex TimerStack::findPath(const PathType &Path) { TTindex CurIndex = 0; // The path is in reverse order (leaf to root), so it needs to be followed in // reverse. for (TTindex Index : reverse_range(Path)) { CurIndex = getChildIndex(CurIndex, Index); } assert(CurIndex); // shouldn't be the sentinel node return CurIndex; } // Pushes a new marker onto the timer stack. void TimerStack::push(TimerIdT ID) { if (!BuildDefs::timers()) return; constexpr bool UpdateCounts = false; update(UpdateCounts); StackTop = getChildIndex(StackTop, ID); assert(StackTop); } // Pops the top marker from the timer stack. Validates via assert() that the // expected marker is popped. void TimerStack::pop(TimerIdT ID) { if (!BuildDefs::timers()) return; constexpr bool UpdateCounts = true; update(UpdateCounts); assert(StackTop); assert(Nodes[StackTop].Parent < StackTop); // Verify that the expected ID is being popped. assert(Nodes[StackTop].Interior == ID); (void)ID; // Verify that the parent's child points to the current stack top. assert(Nodes[Nodes[StackTop].Parent].Children[ID] == StackTop); StackTop = Nodes[StackTop].Parent; } // At a state change (e.g. push or pop), updates the flat and cumulative // timings for everything on the timer stack. void TimerStack::update(bool UpdateCounts) { if (!BuildDefs::timers()) return; ++StateChangeCount; // Whenever the stack is about to change, we grab the time delta since the // last change and add it to all active cumulative elements and to the flat // element for the top of the stack. double Current = timestamp(); double Delta = Current - LastTimestamp; if (StackTop) { TimerIdT Leaf = Nodes[StackTop].Interior; if (Leaf >= LeafTimes.size()) { LeafTimes.resize(Leaf + 1); LeafCounts.resize(Leaf + 1); } LeafTimes[Leaf] += Delta; if (UpdateCounts) ++LeafCounts[Leaf]; } TTindex Prefix = StackTop; while (Prefix) { Nodes[Prefix].Time += Delta; // Only update a leaf node count, not the internal node counts. if (UpdateCounts && Prefix == StackTop) ++Nodes[Prefix].UpdateCount; TTindex Next = Nodes[Prefix].Parent; assert(Next < Prefix); Prefix = Next; } // Capture the next timestamp *after* the updates are finished. This // minimizes how much the timer can perturb the reported timing. The numbers // may not sum to 100%, and the missing amount is indicative of the overhead // of timing. LastTimestamp = timestamp(); } void TimerStack::reset() { if (!BuildDefs::timers()) return; StateChangeCount = 0; FirstTimestamp = LastTimestamp = timestamp(); LeafTimes.assign(LeafTimes.size(), 0); LeafCounts.assign(LeafCounts.size(), 0); for (TimerTreeNode &Node : Nodes) { Node.Time = 0; Node.UpdateCount = 0; } } namespace { using DumpMapType = std::multimap; // Dump the Map items in reverse order of their time contribution. If // AddPercents is true (i.e. for printing "flat times"), it also prints a // cumulative percentage column, and recalculates TotalTime as the sum of all // the individual times so that cumulative percentage adds up to 100%. void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime, bool AddPercents) { if (!BuildDefs::timers()) return; if (AddPercents) { // Recalculate TotalTime as the sum of the individual times. This is // because the individual times generally add up to less than 100% because // of timer overhead. TotalTime = 0; for (const auto &I : Map) { TotalTime += I.first; } } double Sum = 0; for (const auto &I : reverse_range(Map)) { Sum += I.first; if (AddPercents) { Str << llvm::format(" %10.6f %4.1f%% %5.1f%% ", I.first, I.first * 100 / TotalTime, Sum * 100 / TotalTime) << I.second << "\n"; } else { Str << llvm::format(" %10.6f %4.1f%% ", I.first, I.first * 100 / TotalTime) << I.second << "\n"; } } } } // end of anonymous namespace void TimerStack::dump(Ostream &Str, bool DumpCumulative) { if (!BuildDefs::timers()) return; constexpr bool UpdateCounts = true; update(UpdateCounts); double TotalTime = LastTimestamp - FirstTimestamp; assert(TotalTime); char PrefixStr[30]; if (DumpCumulative) { Str << Name << " - Cumulative times:\n" " Seconds Pct EventCnt TimerPath\n"; DumpMapType CumulativeMap; for (TTindex i = 1; i < Nodes.size(); ++i) { TTindex Prefix = i; std::string Suffix = ""; while (Prefix) { if (Suffix.empty()) Suffix = IDs[Nodes[Prefix].Interior]; else Suffix = IDs[Nodes[Prefix].Interior] + "." + Suffix; assert(Nodes[Prefix].Parent < Prefix); Prefix = Nodes[Prefix].Parent; } snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ", Nodes[i].UpdateCount); CumulativeMap.insert(std::make_pair(Nodes[i].Time, PrefixStr + Suffix)); } constexpr bool NoAddPercents = false; dumpHelper(Str, CumulativeMap, TotalTime, NoAddPercents); } Str << Name << " - Flat times:\n" " Seconds Pct CumPct EventCnt TimerName\n"; DumpMapType FlatMap; for (TimerIdT i = 0; i < LeafTimes.size(); ++i) { if (LeafCounts[i]) { snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ", LeafCounts[i]); FlatMap.insert(std::make_pair(LeafTimes[i], PrefixStr + IDs[i])); } } constexpr bool AddPercents = true; dumpHelper(Str, FlatMap, TotalTime, AddPercents); Str << "Number of timer updates: " << StateChangeCount << "\n"; } double TimerStack::timestamp() { // TODO: Implement in terms of std::chrono for C++11. return llvm::TimeRecord::getCurrentTime(false).getWallTime(); } } // end of namespace Ice