1 //===- 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 //===----------------------------------------------------------------------===//
9 ///
10 /// \file
11 /// \brief Defines the TimerTree class, which tracks flat and cumulative
12 /// execution time collection of call chains.
13 ///
14 //===----------------------------------------------------------------------===//
15
16 #include "IceTimerTree.h"
17
18 #include "IceDefs.h"
19
20 #ifdef __clang__
21 #pragma clang diagnostic push
22 #pragma clang diagnostic ignored "-Wunused-parameter"
23 #endif // __clang__
24
25 #include "llvm/Support/Format.h"
26 #include "llvm/Support/Timer.h"
27
28 #ifdef __clang__
29 #pragma clang diagnostic pop
30 #endif // __clang__
31
32 namespace Ice {
33
TimerStack(const std::string & Name)34 TimerStack::TimerStack(const std::string &Name)
35 : Name(Name), FirstTimestamp(timestamp()), LastTimestamp(FirstTimestamp) {
36 if (!BuildDefs::timers())
37 return;
38 Nodes.resize(1); // Reserve Nodes[0] for the root node (sentinel).
39 IDs.resize(TT__num);
40 LeafTimes.resize(TT__num);
41 LeafCounts.resize(TT__num);
42 #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
49 }
50
51 // Returns the unique timer ID for the given Name, creating a new ID if needed.
getTimerID(const std::string & Name)52 TimerIdT TimerStack::getTimerID(const std::string &Name) {
53 if (!BuildDefs::timers())
54 return 0;
55 if (IDsIndex.find(Name) == IDsIndex.end()) {
56 IDsIndex[Name] = IDs.size();
57 IDs.push_back(Name);
58 LeafTimes.push_back(decltype(LeafTimes)::value_type());
59 LeafCounts.push_back(decltype(LeafCounts)::value_type());
60 }
61 return IDsIndex[Name];
62 }
63
64 // 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.
67 TimerStack::TranslationType
translateIDsFrom(const TimerStack & Src)68 TimerStack::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
77 // Merges two timer stacks, by combining and summing corresponding entries.
78 // This timer stack is updated from Src.
mergeFrom(const TimerStack & Src)79 void TimerStack::mergeFrom(const TimerStack &Src) {
80 if (!BuildDefs::timers())
81 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) {
87 // Find the full path to the Src node, translated to path components
88 // corresponding to this timer stack.
89 PathType MyPath = Src.getPath(SrcIndex, Mapping);
90 // Find a node in this timer stack corresponding to the given path,
91 // creating new interior nodes as necessary.
92 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
105 // 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.
getPath(TTindex Index,const TranslationType & Mapping) const108 TimerStack::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
119 // 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.
getChildIndex(TimerStack::TTindex Parent,TimerIdT ID)121 TimerStack::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
135 // Finds a node in the timer stack corresponding to the given path, creating
136 // new interior nodes as necessary.
findPath(const PathType & Path)137 TimerStack::TTindex TimerStack::findPath(const PathType &Path) {
138 TTindex CurIndex = 0;
139 // The path is in reverse order (leaf to root), so it needs to be followed in
140 // reverse.
141 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
148 // Pushes a new marker onto the timer stack.
push(TimerIdT ID)149 void TimerStack::push(TimerIdT ID) {
150 if (!BuildDefs::timers())
151 return;
152 constexpr bool UpdateCounts = false;
153 update(UpdateCounts);
154 StackTop = getChildIndex(StackTop, ID);
155 assert(StackTop);
156 }
157
158 // Pops the top marker from the timer stack. Validates via assert() that the
159 // expected marker is popped.
pop(TimerIdT ID)160 void TimerStack::pop(TimerIdT ID) {
161 if (!BuildDefs::timers())
162 return;
163 constexpr bool UpdateCounts = true;
164 update(UpdateCounts);
165 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
175 // At a state change (e.g. push or pop), updates the flat and cumulative
176 // timings for everything on the timer stack.
update(bool UpdateCounts)177 void TimerStack::update(bool UpdateCounts) {
178 if (!BuildDefs::timers())
179 return;
180 ++StateChangeCount;
181 // 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.
184 double Current = timestamp();
185 double Delta = Current - LastTimestamp;
186 if (StackTop) {
187 TimerIdT Leaf = Nodes[StackTop].Interior;
188 if (Leaf >= LeafTimes.size()) {
189 LeafTimes.resize(Leaf + 1);
190 LeafCounts.resize(Leaf + 1);
191 }
192 LeafTimes[Leaf] += Delta;
193 if (UpdateCounts)
194 ++LeafCounts[Leaf];
195 }
196 TTindex Prefix = StackTop;
197 while (Prefix) {
198 Nodes[Prefix].Time += Delta;
199 // Only update a leaf node count, not the internal node counts.
200 if (UpdateCounts && Prefix == StackTop)
201 ++Nodes[Prefix].UpdateCount;
202 TTindex Next = Nodes[Prefix].Parent;
203 assert(Next < Prefix);
204 Prefix = Next;
205 }
206 // 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.
210 LastTimestamp = timestamp();
211 }
212
reset()213 void TimerStack::reset() {
214 if (!BuildDefs::timers())
215 return;
216 StateChangeCount = 0;
217 FirstTimestamp = LastTimestamp = timestamp();
218 LeafTimes.assign(LeafTimes.size(), 0);
219 LeafCounts.assign(LeafCounts.size(), 0);
220 for (TimerTreeNode &Node : Nodes) {
221 Node.Time = 0;
222 Node.UpdateCount = 0;
223 }
224 }
225
226 namespace {
227
228 using DumpMapType = std::multimap<double, std::string>;
229
230 // 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%.
dumpHelper(Ostream & Str,const DumpMapType & Map,double TotalTime,bool AddPercents)234 void dumpHelper(Ostream &Str, const DumpMapType &Map, double TotalTime,
235 bool AddPercents) {
236 if (!BuildDefs::timers())
237 return;
238 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 }
246 }
247 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)
257 << I.second << "\n";
258 }
259 }
260 }
261
262 } // end of anonymous namespace
263
dump(Ostream & Str,bool DumpCumulative)264 void TimerStack::dump(Ostream &Str, bool DumpCumulative) {
265 if (!BuildDefs::timers())
266 return;
267 constexpr bool UpdateCounts = true;
268 update(UpdateCounts);
269 double TotalTime = LastTimestamp - FirstTimestamp;
270 assert(TotalTime);
271 char PrefixStr[30];
272 if (DumpCumulative) {
273 Str << Name
274 << " - Cumulative times:\n"
275 " Seconds Pct EventCnt TimerPath\n";
276 DumpMapType CumulativeMap;
277 for (TTindex i = 1; i < Nodes.size(); ++i) {
278 TTindex Prefix = i;
279 std::string Suffix = "";
280 while (Prefix) {
281 if (Suffix.empty())
282 Suffix = IDs[Nodes[Prefix].Interior];
283 else
284 Suffix = IDs[Nodes[Prefix].Interior] + "." + Suffix;
285 assert(Nodes[Prefix].Parent < Prefix);
286 Prefix = Nodes[Prefix].Parent;
287 }
288 snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ",
289 Nodes[i].UpdateCount);
290 CumulativeMap.insert(std::make_pair(Nodes[i].Time, PrefixStr + Suffix));
291 }
292 constexpr bool NoAddPercents = false;
293 dumpHelper(Str, CumulativeMap, TotalTime, NoAddPercents);
294 }
295 Str << Name
296 << " - Flat times:\n"
297 " Seconds Pct CumPct EventCnt TimerName\n";
298 DumpMapType FlatMap;
299 for (TimerIdT i = 0; i < LeafTimes.size(); ++i) {
300 if (LeafCounts[i]) {
301 snprintf(PrefixStr, llvm::array_lengthof(PrefixStr), "%9zu ",
302 LeafCounts[i]);
303 FlatMap.insert(std::make_pair(LeafTimes[i], PrefixStr + IDs[i]));
304 }
305 }
306 constexpr bool AddPercents = true;
307 dumpHelper(Str, FlatMap, TotalTime, AddPercents);
308 Str << "Number of timer updates: " << StateChangeCount << "\n";
309 }
310
timestamp()311 double TimerStack::timestamp() {
312 // TODO: Implement in terms of std::chrono for C++11.
313 return llvm::TimeRecord::getCurrentTime(false).getWallTime();
314 }
315
316 } // end of namespace Ice
317