1 //===- PassTiming.cpp -----------------------------------------------------===//
2 //
3 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
4 // See https://llvm.org/LICENSE.txt for license information.
5 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
6 //
7 //===----------------------------------------------------------------------===//
8
9 #include "PassDetail.h"
10 #include "mlir/Pass/PassManager.h"
11 #include "llvm/ADT/MapVector.h"
12 #include "llvm/ADT/STLExtras.h"
13 #include "llvm/ADT/SmallVector.h"
14 #include "llvm/ADT/Statistic.h"
15 #include "llvm/Support/Format.h"
16 #include "llvm/Support/FormatVariadic.h"
17 #include "llvm/Support/Threading.h"
18 #include <chrono>
19
20 using namespace mlir;
21 using namespace mlir::detail;
22
23 constexpr StringLiteral kPassTimingDescription =
24 "... Pass execution timing report ...";
25
26 namespace {
27 /// Simple record class to record timing information.
28 struct TimeRecord {
TimeRecord__anon6b3174650111::TimeRecord29 TimeRecord(double wall = 0.0, double user = 0.0) : wall(wall), user(user) {}
30
operator +=__anon6b3174650111::TimeRecord31 TimeRecord &operator+=(const TimeRecord &other) {
32 wall += other.wall;
33 user += other.user;
34 return *this;
35 }
36
37 /// Print the current time record to 'os', with a breakdown showing
38 /// contributions to the give 'total' time record.
print__anon6b3174650111::TimeRecord39 void print(raw_ostream &os, const TimeRecord &total) {
40 if (total.user != total.wall)
41 os << llvm::format(" %7.4f (%5.1f%%) ", user,
42 100.0 * user / total.user);
43 os << llvm::format(" %7.4f (%5.1f%%) ", wall, 100.0 * wall / total.wall);
44 }
45
46 double wall, user;
47 };
48
49 /// An enumeration of the different types of timers.
50 enum class TimerKind {
51 /// This timer represents an ordered collection of pass timers, corresponding
52 /// to a pass pipeline.
53 Pipeline,
54
55 /// This timer represents a collection of pipeline timers.
56 PipelineCollection,
57
58 /// This timer represents an analysis or pass timer.
59 PassOrAnalysis
60 };
61
62 struct Timer {
Timer__anon6b3174650111::Timer63 explicit Timer(std::string &&name, TimerKind kind)
64 : name(std::move(name)), kind(kind) {}
65
66 /// Start the timer.
start__anon6b3174650111::Timer67 void start() { startTime = std::chrono::system_clock::now(); }
68
69 /// Stop the timer.
stop__anon6b3174650111::Timer70 void stop() {
71 auto newTime = std::chrono::system_clock::now() - startTime;
72 wallTime += newTime;
73 userTime += newTime;
74 }
75
76 /// Get or create a child timer with the provided name and id.
getChildTimer__anon6b3174650111::Timer77 Timer *getChildTimer(const void *id, TimerKind kind,
78 std::function<std::string()> &&nameBuilder) {
79 auto &child = children[id];
80 if (!child)
81 child = std::make_unique<Timer>(nameBuilder(), kind);
82 return child.get();
83 }
84
85 /// Returns the total time for this timer in seconds.
getTotalTime__anon6b3174650111::Timer86 TimeRecord getTotalTime() {
87 // If this is a pass or analysis timer, use the recorded time directly.
88 if (kind == TimerKind::PassOrAnalysis) {
89 return TimeRecord(
90 std::chrono::duration_cast<std::chrono::duration<double>>(wallTime)
91 .count(),
92 std::chrono::duration_cast<std::chrono::duration<double>>(userTime)
93 .count());
94 }
95
96 // Otherwise, accumulate the timing from each of the children.
97 TimeRecord totalTime;
98 for (auto &child : children)
99 totalTime += child.second->getTotalTime();
100 return totalTime;
101 }
102
103 /// A map of unique identifiers to child timers.
104 using ChildrenMap = llvm::MapVector<const void *, std::unique_ptr<Timer>>;
105
106 /// Merge the timing data from 'other' into this timer.
merge__anon6b3174650111::Timer107 void merge(Timer &&other) {
108 if (wallTime < other.wallTime)
109 wallTime = other.wallTime;
110 userTime += other.userTime;
111 mergeChildren(std::move(other.children));
112 }
113
114 /// Merge the timer children in 'otherChildren' with the children of this
115 /// timer.
mergeChildren__anon6b3174650111::Timer116 void mergeChildren(ChildrenMap &&otherChildren) {
117 // Check for an empty children list.
118 if (children.empty()) {
119 children = std::move(otherChildren);
120 return;
121 }
122
123 // Pipeline merges are handled separately as the children are merged
124 // lexicographically.
125 if (kind == TimerKind::Pipeline) {
126 assert(children.size() == otherChildren.size() &&
127 "pipeline merge requires the same number of children");
128 for (auto it : llvm::zip(children, otherChildren))
129 std::get<0>(it).second->merge(std::move(*std::get<1>(it).second));
130 return;
131 }
132
133 // Otherwise, we merge children based upon their timer key.
134 for (auto &otherChild : otherChildren)
135 mergeChild(std::move(otherChild));
136 }
137
138 /// Merge in the given child timer and id into this timer.
mergeChild__anon6b3174650111::Timer139 void mergeChild(ChildrenMap::value_type &&childIt) {
140 auto &child = children[childIt.first];
141 if (!child)
142 child = std::move(childIt.second);
143 else
144 child->merge(std::move(*childIt.second));
145 }
146
147 /// Raw timing information.
148 std::chrono::time_point<std::chrono::system_clock> startTime;
149 std::chrono::nanoseconds wallTime = std::chrono::nanoseconds(0);
150 std::chrono::nanoseconds userTime = std::chrono::nanoseconds(0);
151
152 /// A map of unique identifiers to child timers.
153 ChildrenMap children;
154
155 /// A descriptive name for this timer.
156 std::string name;
157
158 /// The type of timer this instance represents.
159 TimerKind kind;
160 };
161
162 struct PassTiming : public PassInstrumentation {
PassTiming__anon6b3174650111::PassTiming163 PassTiming(std::unique_ptr<PassManager::PassTimingConfig> config)
164 : config(std::move(config)) {}
~PassTiming__anon6b3174650111::PassTiming165 ~PassTiming() override { print(); }
166
167 /// Setup the instrumentation hooks.
168 void runBeforePipeline(Identifier name,
169 const PipelineParentInfo &parentInfo) override;
170 void runAfterPipeline(Identifier name,
171 const PipelineParentInfo &parentInfo) override;
runBeforePass__anon6b3174650111::PassTiming172 void runBeforePass(Pass *pass, Operation *) override { startPassTimer(pass); }
173 void runAfterPass(Pass *pass, Operation *) override;
runAfterPassFailed__anon6b3174650111::PassTiming174 void runAfterPassFailed(Pass *pass, Operation *op) override {
175 runAfterPass(pass, op);
176 }
runBeforeAnalysis__anon6b3174650111::PassTiming177 void runBeforeAnalysis(StringRef name, TypeID id, Operation *) override {
178 startAnalysisTimer(name, id);
179 }
180 void runAfterAnalysis(StringRef, TypeID, Operation *) override;
181
182 /// Print and clear the timing results.
183 void print();
184
185 /// Start a new timer for the given pass.
186 void startPassTimer(Pass *pass);
187
188 /// Start a new timer for the given analysis.
189 void startAnalysisTimer(StringRef name, TypeID id);
190
191 /// Pop the last active timer for the current thread.
popLastActiveTimer__anon6b3174650111::PassTiming192 Timer *popLastActiveTimer() {
193 auto tid = llvm::get_threadid();
194 auto &activeTimers = activeThreadTimers[tid];
195 assert(!activeTimers.empty() && "expected active timer");
196 return activeTimers.pop_back_val();
197 }
198
199 /// Print the timing result in list mode.
200 void printResultsAsList(raw_ostream &os, Timer *root, TimeRecord totalTime);
201
202 /// Print the timing result in pipeline mode.
203 void printResultsAsPipeline(raw_ostream &os, Timer *root,
204 TimeRecord totalTime);
205
206 /// Returns a timer for the provided identifier and name.
getTimer__anon6b3174650111::PassTiming207 Timer *getTimer(const void *id, TimerKind kind,
208 std::function<std::string()> &&nameBuilder) {
209 auto tid = llvm::get_threadid();
210
211 // If there is no active timer then add to the root timer.
212 auto &activeTimers = activeThreadTimers[tid];
213 Timer *parentTimer;
214 if (activeTimers.empty()) {
215 auto &rootTimer = rootTimers[tid];
216 if (!rootTimer)
217 rootTimer = std::make_unique<Timer>("root", TimerKind::Pipeline);
218 parentTimer = rootTimer.get();
219 } else {
220 // Otherwise, add this to the active timer.
221 parentTimer = activeTimers.back();
222 }
223
224 auto timer = parentTimer->getChildTimer(id, kind, std::move(nameBuilder));
225 activeTimers.push_back(timer);
226 return timer;
227 }
228
229 /// The root top level timers for each thread.
230 DenseMap<uint64_t, std::unique_ptr<Timer>> rootTimers;
231
232 /// A stack of the currently active pass timers per thread.
233 DenseMap<uint64_t, SmallVector<Timer *, 4>> activeThreadTimers;
234
235 /// The configuration object to use when printing the timing results.
236 std::unique_ptr<PassManager::PassTimingConfig> config;
237
238 /// A mapping of pipeline timers that need to be merged into the parent
239 /// collection. The timers are mapped to the parent info to merge into.
240 DenseMap<PipelineParentInfo, SmallVector<Timer::ChildrenMap::value_type, 4>>
241 pipelinesToMerge;
242 };
243 } // end anonymous namespace
244
runBeforePipeline(Identifier name,const PipelineParentInfo & parentInfo)245 void PassTiming::runBeforePipeline(Identifier name,
246 const PipelineParentInfo &parentInfo) {
247 // We don't actually want to time the pipelines, they gather their total
248 // from their held passes.
249 getTimer(name.getAsOpaquePointer(), TimerKind::Pipeline,
250 [&] { return ("'" + name.strref() + "' Pipeline").str(); });
251 }
252
runAfterPipeline(Identifier name,const PipelineParentInfo & parentInfo)253 void PassTiming::runAfterPipeline(Identifier name,
254 const PipelineParentInfo &parentInfo) {
255 // Pop the timer for the pipeline.
256 auto tid = llvm::get_threadid();
257 auto &activeTimers = activeThreadTimers[tid];
258 assert(!activeTimers.empty() && "expected active timer");
259 activeTimers.pop_back();
260
261 // If the current thread is the same as the parent, there is nothing left to
262 // do.
263 if (tid == parentInfo.parentThreadID)
264 return;
265
266 // Otherwise, mark the pipeline timer for merging into the correct parent
267 // thread.
268 assert(activeTimers.empty() && "expected parent timer to be root");
269 auto *parentTimer = rootTimers[tid].get();
270 assert(parentTimer->children.size() == 1 &&
271 parentTimer->children.count(name.getAsOpaquePointer()) &&
272 "expected a single pipeline timer");
273 pipelinesToMerge[parentInfo].push_back(
274 std::move(*parentTimer->children.begin()));
275 rootTimers.erase(tid);
276 }
277
278 /// Start a new timer for the given pass.
startPassTimer(Pass * pass)279 void PassTiming::startPassTimer(Pass *pass) {
280 auto kind = isa<OpToOpPassAdaptor>(pass) ? TimerKind::PipelineCollection
281 : TimerKind::PassOrAnalysis;
282 Timer *timer = getTimer(pass, kind, [pass]() -> std::string {
283 if (auto *adaptor = dyn_cast<OpToOpPassAdaptor>(pass))
284 return adaptor->getAdaptorName();
285 return std::string(pass->getName());
286 });
287
288 // We don't actually want to time the adaptor passes, they gather their total
289 // from their held passes.
290 if (!isa<OpToOpPassAdaptor>(pass))
291 timer->start();
292 }
293
294 /// Start a new timer for the given analysis.
startAnalysisTimer(StringRef name,TypeID id)295 void PassTiming::startAnalysisTimer(StringRef name, TypeID id) {
296 Timer *timer = getTimer(id.getAsOpaquePointer(), TimerKind::PassOrAnalysis,
297 [name] { return "(A) " + name.str(); });
298 timer->start();
299 }
300
301 /// Stop a pass timer.
runAfterPass(Pass * pass,Operation *)302 void PassTiming::runAfterPass(Pass *pass, Operation *) {
303 Timer *timer = popLastActiveTimer();
304
305 // If this is a pass adaptor, then we need to merge in the timing data for the
306 // pipelines running on other threads.
307 if (isa<OpToOpPassAdaptor>(pass)) {
308 auto toMerge = pipelinesToMerge.find({llvm::get_threadid(), pass});
309 if (toMerge != pipelinesToMerge.end()) {
310 for (auto &it : toMerge->second)
311 timer->mergeChild(std::move(it));
312 pipelinesToMerge.erase(toMerge);
313 }
314 return;
315 }
316
317 timer->stop();
318 }
319
320 /// Stop a timer.
runAfterAnalysis(StringRef,TypeID,Operation *)321 void PassTiming::runAfterAnalysis(StringRef, TypeID, Operation *) {
322 popLastActiveTimer()->stop();
323 }
324
325 /// Utility to print the timer heading information.
printTimerHeader(raw_ostream & os,TimeRecord total)326 static void printTimerHeader(raw_ostream &os, TimeRecord total) {
327 os << "===" << std::string(73, '-') << "===\n";
328 // Figure out how many spaces to description name.
329 unsigned padding = (80 - kPassTimingDescription.size()) / 2;
330 os.indent(padding) << kPassTimingDescription << '\n';
331 os << "===" << std::string(73, '-') << "===\n";
332
333 // Print the total time followed by the section headers.
334 os << llvm::format(" Total Execution Time: %5.4f seconds\n\n", total.wall);
335 if (total.user != total.wall)
336 os << " ---User Time---";
337 os << " ---Wall Time--- --- Name ---\n";
338 }
339
340 /// Utility to print a single line entry in the timer output.
printTimeEntry(raw_ostream & os,unsigned indent,StringRef name,TimeRecord time,TimeRecord totalTime)341 static void printTimeEntry(raw_ostream &os, unsigned indent, StringRef name,
342 TimeRecord time, TimeRecord totalTime) {
343 time.print(os, totalTime);
344 os.indent(indent) << name << "\n";
345 }
346
347 /// Print out the current timing information.
print()348 void PassTiming::print() {
349 // Don't print anything if there is no timing data.
350 if (rootTimers.empty())
351 return;
352
353 assert(rootTimers.size() == 1 && "expected one remaining root timer");
354
355 auto printCallback = [&](raw_ostream &os) {
356 auto &rootTimer = rootTimers.begin()->second;
357 // Print the timer header.
358 TimeRecord totalTime = rootTimer->getTotalTime();
359 printTimerHeader(os, totalTime);
360 // Defer to a specialized printer for each display mode.
361 switch (config->getDisplayMode()) {
362 case PassDisplayMode::List:
363 printResultsAsList(os, rootTimer.get(), totalTime);
364 break;
365 case PassDisplayMode::Pipeline:
366 printResultsAsPipeline(os, rootTimer.get(), totalTime);
367 break;
368 }
369 printTimeEntry(os, 0, "Total", totalTime, totalTime);
370 os.flush();
371
372 // Reset root timers.
373 rootTimers.clear();
374 activeThreadTimers.clear();
375 };
376
377 config->printTiming(printCallback);
378 }
379
380 // The default implementation for printTiming uses
381 // `llvm::CreateInfoOutputFile()` as stream, it can be overridden by clients
382 // to customize the output.
printTiming(PrintCallbackFn printCallback)383 void PassManager::PassTimingConfig::printTiming(PrintCallbackFn printCallback) {
384 printCallback(*llvm::CreateInfoOutputFile());
385 }
386
387 /// Print the timing result in list mode.
printResultsAsList(raw_ostream & os,Timer * root,TimeRecord totalTime)388 void PassTiming::printResultsAsList(raw_ostream &os, Timer *root,
389 TimeRecord totalTime) {
390 llvm::StringMap<TimeRecord> mergedTimings;
391
392 std::function<void(Timer *)> addTimer = [&](Timer *timer) {
393 // Only add timing information for passes and analyses.
394 if (timer->kind == TimerKind::PassOrAnalysis)
395 mergedTimings[timer->name] += timer->getTotalTime();
396 for (auto &children : timer->children)
397 addTimer(children.second.get());
398 };
399
400 // Add each of the top level timers.
401 for (auto &topLevelTimer : root->children)
402 addTimer(topLevelTimer.second.get());
403
404 // Sort the timing information by wall time.
405 std::vector<std::pair<StringRef, TimeRecord>> timerNameAndTime;
406 for (auto &it : mergedTimings)
407 timerNameAndTime.emplace_back(it.first(), it.second);
408 llvm::array_pod_sort(timerNameAndTime.begin(), timerNameAndTime.end(),
409 [](const std::pair<StringRef, TimeRecord> *lhs,
410 const std::pair<StringRef, TimeRecord> *rhs) {
411 return llvm::array_pod_sort_comparator<double>(
412 &rhs->second.wall, &lhs->second.wall);
413 });
414
415 // Print the timing information sequentially.
416 for (auto &timeData : timerNameAndTime)
417 printTimeEntry(os, 0, timeData.first, timeData.second, totalTime);
418 }
419
420 /// Print the timing result in pipeline mode.
printResultsAsPipeline(raw_ostream & os,Timer * root,TimeRecord totalTime)421 void PassTiming::printResultsAsPipeline(raw_ostream &os, Timer *root,
422 TimeRecord totalTime) {
423 std::function<void(unsigned, Timer *)> printTimer = [&](unsigned indent,
424 Timer *timer) {
425 // If this is a timer for a pipeline collection and the collection only has
426 // one pipeline child, then only print the child.
427 if (timer->kind == TimerKind::PipelineCollection &&
428 timer->children.size() == 1)
429 return printTimer(indent, timer->children.begin()->second.get());
430
431 printTimeEntry(os, indent, timer->name, timer->getTotalTime(), totalTime);
432
433 // If this timer is a pipeline, then print the children in-order.
434 if (timer->kind == TimerKind::Pipeline) {
435 for (auto &child : timer->children)
436 printTimer(indent + 2, child.second.get());
437 return;
438 }
439
440 // Otherwise, sort the children by name to give a deterministic ordering
441 // when emitting the time.
442 SmallVector<Timer *, 4> children;
443 children.reserve(timer->children.size());
444 for (auto &child : timer->children)
445 children.push_back(child.second.get());
446 llvm::array_pod_sort(children.begin(), children.end(),
447 [](Timer *const *lhs, Timer *const *rhs) {
448 return (*lhs)->name.compare((*rhs)->name);
449 });
450 for (auto &child : children)
451 printTimer(indent + 2, child);
452 };
453
454 // Print each of the top level timers.
455 for (auto &topLevelTimer : root->children)
456 printTimer(0, topLevelTimer.second.get());
457 }
458
459 // Out-of-line as key function.
~PassTimingConfig()460 PassManager::PassTimingConfig::~PassTimingConfig() {}
461
462 //===----------------------------------------------------------------------===//
463 // PassManager
464 //===----------------------------------------------------------------------===//
465
466 /// Add an instrumentation to time the execution of passes and the computation
467 /// of analyses.
enableTiming(std::unique_ptr<PassTimingConfig> config)468 void PassManager::enableTiming(std::unique_ptr<PassTimingConfig> config) {
469 // Check if pass timing is already enabled.
470 if (passTiming)
471 return;
472 if (!config)
473 config = std::make_unique<PassManager::PassTimingConfig>();
474 addInstrumentation(std::make_unique<PassTiming>(std::move(config)));
475 passTiming = true;
476 }
477