blob: 35295ae6953171a8dbdcdc5625e15a10c0ba25fc [file] [log] [blame]
Jim Stichnothc4554d72014-09-30 16:49:38 -07001//===- subzero/src/IceTimerTree.cpp - Pass timer defs ---------------------===//
2//
3// The Subzero Code Generator
4//
5// This file is distributed under the University of Illinois Open Source
6// License. See LICENSE.TXT for details.
7//
8//===----------------------------------------------------------------------===//
Andrew Scull9612d322015-07-06 14:53:25 -07009///
10/// \file
Jim Stichnoth92a6e5b2015-12-02 16:52:44 -080011/// \brief Defines the TimerTree class, which tracks flat and cumulative
Andrew Scull57e12682015-09-16 11:30:19 -070012/// execution time collection of call chains.
Andrew Scull9612d322015-07-06 14:53:25 -070013///
Jim Stichnothc4554d72014-09-30 16:49:38 -070014//===----------------------------------------------------------------------===//
15
John Porto67f8de92015-06-25 10:14:17 -070016#include "IceTimerTree.h"
Jim Stichnoth9c234e22014-10-01 09:28:21 -070017
Jim Stichnothc4554d72014-09-30 16:49:38 -070018#include "IceDefs.h"
Jim Stichnoth98da9662015-06-27 06:38:08 -070019
Jim Stichnothb0051df2016-01-13 11:39:15 -080020#ifdef __clang__
Jim Stichnoth98da9662015-06-27 06:38:08 -070021#pragma clang diagnostic push
22#pragma clang diagnostic ignored "-Wunused-parameter"
Jim Stichnothb0051df2016-01-13 11:39:15 -080023#endif // __clang__
24
Jim Stichnothd72385f2016-04-06 12:21:14 -070025#include "llvm/Support/Format.h"
John Porto67f8de92015-06-25 10:14:17 -070026#include "llvm/Support/Timer.h"
Jim Stichnothb0051df2016-01-13 11:39:15 -080027
28#ifdef __clang__
Jim Stichnoth98da9662015-06-27 06:38:08 -070029#pragma clang diagnostic pop
Jim Stichnothb0051df2016-01-13 11:39:15 -080030#endif // __clang__
Jim Stichnothc4554d72014-09-30 16:49:38 -070031
32namespace Ice {
33
Jim Stichnoth467ffe52016-03-29 15:01:06 -070034TimerStack::TimerStack(const std::string &Name)
Jim Stichnotheafb56c2015-06-22 10:35:22 -070035 : Name(Name), FirstTimestamp(timestamp()), LastTimestamp(FirstTimestamp) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -080036 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -080037 return;
Jim Stichnoth380d7b92015-01-30 13:10:39 -080038 Nodes.resize(1); // Reserve Nodes[0] for the root node (sentinel).
Jim Stichnoth8363a062014-10-07 10:02:38 -070039 IDs.resize(TT__num);
Jim Stichnoth380d7b92015-01-30 13:10:39 -080040 LeafTimes.resize(TT__num);
41 LeafCounts.resize(TT__num);
Jim Stichnoth8363a062014-10-07 10:02:38 -070042#define STR(s) #s
43#define X(tag) \
44 IDs[TT_##tag] = STR(tag); \
45 IDsIndex[STR(tag)] = TT_##tag;
46 TIMERTREE_TABLE;
47#undef X
48#undef STR
Jim Stichnothc4554d72014-09-30 16:49:38 -070049}
50
Andrew Scull57e12682015-09-16 11:30:19 -070051// Returns the unique timer ID for the given Name, creating a new ID if needed.
Jim Stichnoth467ffe52016-03-29 15:01:06 -070052TimerIdT TimerStack::getTimerID(const std::string &Name) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -080053 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -080054 return 0;
Jim Stichnoth8363a062014-10-07 10:02:38 -070055 if (IDsIndex.find(Name) == IDsIndex.end()) {
56 IDsIndex[Name] = IDs.size();
57 IDs.push_back(Name);
Jim Stichnoth380d7b92015-01-30 13:10:39 -080058 LeafTimes.push_back(decltype(LeafTimes)::value_type());
59 LeafCounts.push_back(decltype(LeafCounts)::value_type());
Jim Stichnothc4554d72014-09-30 16:49:38 -070060 }
Jim Stichnoth8363a062014-10-07 10:02:38 -070061 return IDsIndex[Name];
Jim Stichnothc4554d72014-09-30 16:49:38 -070062}
63
Andrew Scull57e12682015-09-16 11:30:19 -070064// Creates a mapping from TimerIdT (leaf) values in the Src timer stack into
65// TimerIdT values in this timer stack. Creates new entries in this timer stack
66// as needed.
Jim Stichnoth380d7b92015-01-30 13:10:39 -080067TimerStack::TranslationType
68TimerStack::translateIDsFrom(const TimerStack &Src) {
69 size_t Size = Src.IDs.size();
70 TranslationType Mapping(Size);
71 for (TimerIdT i = 0; i < Size; ++i) {
72 Mapping[i] = getTimerID(Src.IDs[i]);
73 }
74 return Mapping;
75}
76
Andrew Scull57e12682015-09-16 11:30:19 -070077// Merges two timer stacks, by combining and summing corresponding entries.
78// This timer stack is updated from Src.
Jim Stichnoth380d7b92015-01-30 13:10:39 -080079void TimerStack::mergeFrom(const TimerStack &Src) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -080080 if (!BuildDefs::timers())
Jim Stichnoth380d7b92015-01-30 13:10:39 -080081 return;
82 TranslationType Mapping = translateIDsFrom(Src);
83 TTindex SrcIndex = 0;
84 for (const TimerTreeNode &SrcNode : Src.Nodes) {
85 // The first node is reserved as a sentinel, so avoid it.
86 if (SrcIndex > 0) {
Andrew Scull57e12682015-09-16 11:30:19 -070087 // Find the full path to the Src node, translated to path components
88 // corresponding to this timer stack.
Jim Stichnoth380d7b92015-01-30 13:10:39 -080089 PathType MyPath = Src.getPath(SrcIndex, Mapping);
Andrew Scull57e12682015-09-16 11:30:19 -070090 // Find a node in this timer stack corresponding to the given path,
91 // creating new interior nodes as necessary.
Jim Stichnoth380d7b92015-01-30 13:10:39 -080092 TTindex MyIndex = findPath(MyPath);
93 Nodes[MyIndex].Time += SrcNode.Time;
94 Nodes[MyIndex].UpdateCount += SrcNode.UpdateCount;
95 }
96 ++SrcIndex;
97 }
98 for (TimerIdT i = 0; i < Src.LeafTimes.size(); ++i) {
99 LeafTimes[Mapping[i]] += Src.LeafTimes[i];
100 LeafCounts[Mapping[i]] += Src.LeafCounts[i];
101 }
102 StateChangeCount += Src.StateChangeCount;
103}
104
Andrew Scull57e12682015-09-16 11:30:19 -0700105// Constructs a path consisting of the sequence of leaf values leading to a
106// given node, with the Mapping translation applied to the leaf values. The
107// path ends up being in "reverse" order, i.e. from leaf to root.
Jim Stichnoth380d7b92015-01-30 13:10:39 -0800108TimerStack::PathType TimerStack::getPath(TTindex Index,
109 const TranslationType &Mapping) const {
110 PathType Path;
111 while (Index) {
112 Path.push_back(Mapping[Nodes[Index].Interior]);
113 assert(Nodes[Index].Parent < Index);
114 Index = Nodes[Index].Parent;
115 }
116 return Path;
117}
118
Andrew Scull57e12682015-09-16 11:30:19 -0700119// Given a parent node and a leaf ID, returns the index of the parent's child
120// ID, creating a new node for the child as necessary.
Jim Stichnoth380d7b92015-01-30 13:10:39 -0800121TimerStack::TTindex TimerStack::getChildIndex(TimerStack::TTindex Parent,
122 TimerIdT ID) {
123 if (Nodes[Parent].Children.size() <= ID)
124 Nodes[Parent].Children.resize(ID + 1);
125 if (Nodes[Parent].Children[ID] == 0) {
126 TTindex Size = Nodes.size();
127 Nodes[Parent].Children[ID] = Size;
128 Nodes.resize(Size + 1);
129 Nodes[Size].Parent = Parent;
130 Nodes[Size].Interior = ID;
131 }
132 return Nodes[Parent].Children[ID];
133}
134
Andrew Scull57e12682015-09-16 11:30:19 -0700135// Finds a node in the timer stack corresponding to the given path, creating
136// new interior nodes as necessary.
Jim Stichnoth380d7b92015-01-30 13:10:39 -0800137TimerStack::TTindex TimerStack::findPath(const PathType &Path) {
138 TTindex CurIndex = 0;
Andrew Scull57e12682015-09-16 11:30:19 -0700139 // The path is in reverse order (leaf to root), so it needs to be followed in
140 // reverse.
Jim Stichnoth380d7b92015-01-30 13:10:39 -0800141 for (TTindex Index : reverse_range(Path)) {
142 CurIndex = getChildIndex(CurIndex, Index);
143 }
144 assert(CurIndex); // shouldn't be the sentinel node
145 return CurIndex;
146}
147
Jim Stichnothc4554d72014-09-30 16:49:38 -0700148// Pushes a new marker onto the timer stack.
149void TimerStack::push(TimerIdT ID) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800150 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -0800151 return;
Jim Stichnoth5bff61c2015-10-28 09:26:00 -0700152 constexpr bool UpdateCounts = false;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700153 update(UpdateCounts);
Jim Stichnoth380d7b92015-01-30 13:10:39 -0800154 StackTop = getChildIndex(StackTop, ID);
155 assert(StackTop);
Jim Stichnothc4554d72014-09-30 16:49:38 -0700156}
157
Andrew Scull57e12682015-09-16 11:30:19 -0700158// Pops the top marker from the timer stack. Validates via assert() that the
159// expected marker is popped.
Jim Stichnothc4554d72014-09-30 16:49:38 -0700160void TimerStack::pop(TimerIdT ID) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800161 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -0800162 return;
Jim Stichnoth5bff61c2015-10-28 09:26:00 -0700163 constexpr bool UpdateCounts = true;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700164 update(UpdateCounts);
Jim Stichnothc4554d72014-09-30 16:49:38 -0700165 assert(StackTop);
166 assert(Nodes[StackTop].Parent < StackTop);
167 // Verify that the expected ID is being popped.
168 assert(Nodes[StackTop].Interior == ID);
169 (void)ID;
170 // Verify that the parent's child points to the current stack top.
171 assert(Nodes[Nodes[StackTop].Parent].Children[ID] == StackTop);
172 StackTop = Nodes[StackTop].Parent;
173}
174
Andrew Scull57e12682015-09-16 11:30:19 -0700175// At a state change (e.g. push or pop), updates the flat and cumulative
176// timings for everything on the timer stack.
Jim Stichnothabce6e52014-10-14 11:09:27 -0700177void TimerStack::update(bool UpdateCounts) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800178 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -0800179 return;
Jim Stichnothc4554d72014-09-30 16:49:38 -0700180 ++StateChangeCount;
Andrew Scull57e12682015-09-16 11:30:19 -0700181 // Whenever the stack is about to change, we grab the time delta since the
182 // last change and add it to all active cumulative elements and to the flat
183 // element for the top of the stack.
Jim Stichnothc4554d72014-09-30 16:49:38 -0700184 double Current = timestamp();
185 double Delta = Current - LastTimestamp;
Jim Stichnothc4554d72014-09-30 16:49:38 -0700186 if (StackTop) {
187 TimerIdT Leaf = Nodes[StackTop].Interior;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700188 if (Leaf >= LeafTimes.size()) {
Jim Stichnothc4554d72014-09-30 16:49:38 -0700189 LeafTimes.resize(Leaf + 1);
Jim Stichnothabce6e52014-10-14 11:09:27 -0700190 LeafCounts.resize(Leaf + 1);
191 }
Jim Stichnothc4554d72014-09-30 16:49:38 -0700192 LeafTimes[Leaf] += Delta;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700193 if (UpdateCounts)
194 ++LeafCounts[Leaf];
Jim Stichnothc4554d72014-09-30 16:49:38 -0700195 }
196 TTindex Prefix = StackTop;
197 while (Prefix) {
198 Nodes[Prefix].Time += Delta;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700199 // Only update a leaf node count, not the internal node counts.
200 if (UpdateCounts && Prefix == StackTop)
201 ++Nodes[Prefix].UpdateCount;
Jim Stichnothc4554d72014-09-30 16:49:38 -0700202 TTindex Next = Nodes[Prefix].Parent;
203 assert(Next < Prefix);
204 Prefix = Next;
205 }
Andrew Scull57e12682015-09-16 11:30:19 -0700206 // Capture the next timestamp *after* the updates are finished. This
207 // minimizes how much the timer can perturb the reported timing. The numbers
208 // may not sum to 100%, and the missing amount is indicative of the overhead
209 // of timing.
Jim Stichnoth47752552014-10-13 17:15:08 -0700210 LastTimestamp = timestamp();
Jim Stichnothc4554d72014-09-30 16:49:38 -0700211}
212
Jim Stichnothd14b1a02014-10-08 08:28:36 -0700213void TimerStack::reset() {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800214 if (!BuildDefs::timers())
Jim Stichnoth1c44d812014-12-08 14:57:52 -0800215 return;
Jim Stichnothd14b1a02014-10-08 08:28:36 -0700216 StateChangeCount = 0;
217 FirstTimestamp = LastTimestamp = timestamp();
218 LeafTimes.assign(LeafTimes.size(), 0);
Jim Stichnothabce6e52014-10-14 11:09:27 -0700219 LeafCounts.assign(LeafCounts.size(), 0);
Jim Stichnothd14b1a02014-10-08 08:28:36 -0700220 for (TimerTreeNode &Node : Nodes) {
221 Node.Time = 0;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700222 Node.UpdateCount = 0;
Jim Stichnothd14b1a02014-10-08 08:28:36 -0700223 }
224}
225
Jim Stichnothc4554d72014-09-30 16:49:38 -0700226namespace {
227
Jim Stichnoth467ffe52016-03-29 15:01:06 -0700228using DumpMapType = std::multimap<double, std::string>;
Jim Stichnothc4554d72014-09-30 16:49:38 -0700229
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700230// Dump the Map items in reverse order of their time contribution. If
231// AddPercents is true (i.e. for printing "flat times"), it also prints a
232// cumulative percentage column, and recalculates TotalTime as the sum of all
233// the individual times so that cumulative percentage adds up to 100%.
234void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime,
235 bool AddPercents) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800236 if (!BuildDefs::timers())
Karl Schimpfb6c96af2014-11-17 10:58:39 -0800237 return;
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700238 if (AddPercents) {
239 // Recalculate TotalTime as the sum of the individual times. This is
240 // because the individual times generally add up to less than 100% because
241 // of timer overhead.
242 TotalTime = 0;
243 for (const auto &I : Map) {
244 TotalTime += I.first;
245 }
Jim Stichnothc4554d72014-09-30 16:49:38 -0700246 }
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700247 double Sum = 0;
248 for (const auto &I : reverse_range(Map)) {
249 Sum += I.first;
250 if (AddPercents) {
251 Str << llvm::format(" %10.6f %4.1f%% %5.1f%% ", I.first,
252 I.first * 100 / TotalTime, Sum * 100 / TotalTime)
253 << I.second << "\n";
254 } else {
255 Str << llvm::format(" %10.6f %4.1f%% ", I.first,
256 I.first * 100 / TotalTime) << I.second << "\n";
257 }
258 }
Jim Stichnothabce6e52014-10-14 11:09:27 -0700259}
260
Jim Stichnothc4554d72014-09-30 16:49:38 -0700261} // end of anonymous namespace
262
Jim Stichnoth8363a062014-10-07 10:02:38 -0700263void TimerStack::dump(Ostream &Str, bool DumpCumulative) {
Jim Stichnothb88d8c82016-03-11 15:33:00 -0800264 if (!BuildDefs::timers())
Karl Schimpfb6c96af2014-11-17 10:58:39 -0800265 return;
Jim Stichnoth5bff61c2015-10-28 09:26:00 -0700266 constexpr bool UpdateCounts = true;
Jim Stichnothabce6e52014-10-14 11:09:27 -0700267 update(UpdateCounts);
Jim Stichnothc4554d72014-09-30 16:49:38 -0700268 double TotalTime = LastTimestamp - FirstTimestamp;
269 assert(TotalTime);
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700270 char PrefixStr[30];
Jim Stichnoth8363a062014-10-07 10:02:38 -0700271 if (DumpCumulative) {
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700272 Str << Name << " - Cumulative times:\n"
273 " Seconds Pct EventCnt TimerPath\n";
Jim Stichnoth8363a062014-10-07 10:02:38 -0700274 DumpMapType CumulativeMap;
275 for (TTindex i = 1; i < Nodes.size(); ++i) {
276 TTindex Prefix = i;
Jim Stichnoth467ffe52016-03-29 15:01:06 -0700277 std::string Suffix = "";
Jim Stichnoth8363a062014-10-07 10:02:38 -0700278 while (Prefix) {
279 if (Suffix.empty())
280 Suffix = IDs[Nodes[Prefix].Interior];
281 else
282 Suffix = IDs[Nodes[Prefix].Interior] + "." + Suffix;
283 assert(Nodes[Prefix].Parent < Prefix);
284 Prefix = Nodes[Prefix].Parent;
285 }
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700286 snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ",
Jim Stichnothabce6e52014-10-14 11:09:27 -0700287 Nodes[i].UpdateCount);
288 CumulativeMap.insert(std::make_pair(Nodes[i].Time, PrefixStr + Suffix));
Jim Stichnothc4554d72014-09-30 16:49:38 -0700289 }
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700290 constexpr bool NoAddPercents = false;
291 dumpHelper(Str, CumulativeMap, TotalTime, NoAddPercents);
Jim Stichnothc4554d72014-09-30 16:49:38 -0700292 }
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700293 Str << Name << " - Flat times:\n"
294 " Seconds Pct CumPct EventCnt TimerName\n";
Jim Stichnothc4554d72014-09-30 16:49:38 -0700295 DumpMapType FlatMap;
296 for (TimerIdT i = 0; i < LeafTimes.size(); ++i) {
Jim Stichnothabce6e52014-10-14 11:09:27 -0700297 if (LeafCounts[i]) {
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700298 snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ",
Jim Stichnothabce6e52014-10-14 11:09:27 -0700299 LeafCounts[i]);
300 FlatMap.insert(std::make_pair(LeafTimes[i], PrefixStr + IDs[i]));
301 }
Jim Stichnothc4554d72014-09-30 16:49:38 -0700302 }
Jim Stichnoth9a23e432016-04-08 17:09:29 -0700303 constexpr bool AddPercents = true;
304 dumpHelper(Str, FlatMap, TotalTime, AddPercents);
Jim Stichnothc4554d72014-09-30 16:49:38 -0700305 Str << "Number of timer updates: " << StateChangeCount << "\n";
306}
307
Jim Stichnoth9c234e22014-10-01 09:28:21 -0700308double TimerStack::timestamp() {
309 // TODO: Implement in terms of std::chrono for C++11.
310 return llvm::TimeRecord::getCurrentTime(false).getWallTime();
311}
312
Jim Stichnothc4554d72014-09-30 16:49:38 -0700313} // end of namespace Ice