636 lines · cpp
1//===- Timing.cpp - Execution time measurement facilities -----------------===//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-exception6//7//===----------------------------------------------------------------------===//8//9// Facilities to measure and provide statistics on execution time.10//11//===----------------------------------------------------------------------===//12 13#include "mlir/Support/Timing.h"14#include "mlir/Support/ThreadLocalCache.h"15#include "llvm/ADT/MapVector.h"16#include "llvm/ADT/Statistic.h"17#include "llvm/ADT/StringMap.h"18#include "llvm/ADT/StringSet.h"19#include "llvm/Support/Allocator.h"20#include "llvm/Support/CommandLine.h"21#include "llvm/Support/Format.h"22#include "llvm/Support/ManagedStatic.h"23#include "llvm/Support/RWMutex.h"24#include "llvm/Support/Threading.h"25#include "llvm/Support/raw_ostream.h"26 27#include <chrono>28#include <optional>29 30using namespace mlir;31using namespace detail;32using DisplayMode = DefaultTimingManager::DisplayMode;33using OutputFormat = DefaultTimingManager::OutputFormat;34 35constexpr llvm::StringLiteral kTimingDescription =36 "... Execution time report ...";37 38//===----------------------------------------------------------------------===//39// TimingManager40//===----------------------------------------------------------------------===//41 42namespace mlir {43namespace detail {44/// Private implementation details of the `TimingManager`.45class TimingManagerImpl {46public:47 // Identifier allocator, map, and mutex for thread safety.48 llvm::BumpPtrAllocator identifierAllocator;49 llvm::StringSet<llvm::BumpPtrAllocator &> identifiers;50 llvm::sys::SmartRWMutex<true> identifierMutex;51 52 /// A thread local cache of identifiers to reduce lock contention.53 ThreadLocalCache<54 llvm::StringMap<llvm::StringMapEntry<llvm::EmptyStringSetTag> *>>55 localIdentifierCache;56 57 TimingManagerImpl() : identifiers(identifierAllocator) {}58};59} // namespace detail60} // namespace mlir61 62TimingManager::TimingManager() : impl(std::make_unique<TimingManagerImpl>()) {}63 64TimingManager::~TimingManager() = default;65 66/// Get the root timer of this timing manager.67Timer TimingManager::getRootTimer() {68 auto rt = rootTimer();69 return rt ? Timer(*this, *rt) : Timer();70}71 72/// Get the root timer of this timing manager wrapped in a `TimingScope`.73TimingScope TimingManager::getRootScope() {74 return TimingScope(getRootTimer());75}76 77//===----------------------------------------------------------------------===//78// Identifier uniquing79//===----------------------------------------------------------------------===//80 81/// Return an identifier for the specified string.82TimingIdentifier TimingIdentifier::get(StringRef str, TimingManager &tm) {83 // Check for an existing instance in the local cache.84 auto &impl = *tm.impl;85 auto *&localEntry = (*impl.localIdentifierCache)[str];86 if (localEntry)87 return TimingIdentifier(localEntry);88 89 // Check for an existing identifier in read-only mode.90 {91 llvm::sys::SmartScopedReader<true> contextLock(impl.identifierMutex);92 auto it = impl.identifiers.find(str);93 if (it != impl.identifiers.end()) {94 localEntry = &*it;95 return TimingIdentifier(localEntry);96 }97 }98 99 // Acquire a writer-lock so that we can safely create the new instance.100 llvm::sys::SmartScopedWriter<true> contextLock(impl.identifierMutex);101 auto it = impl.identifiers.insert(str).first;102 localEntry = &*it;103 return TimingIdentifier(localEntry);104}105 106//===----------------------------------------------------------------------===//107// Helpers for time record printing108//===----------------------------------------------------------------------===//109 110namespace {111 112class OutputTextStrategy : public OutputStrategy {113public:114 OutputTextStrategy(raw_ostream &os) : OutputStrategy(os) {}115 116 void printHeader(const TimeRecord &total) override {117 // Figure out how many spaces to description name.118 unsigned padding = (80 - kTimingDescription.size()) / 2;119 os << "===" << std::string(73, '-') << "===\n";120 os.indent(padding) << kTimingDescription << '\n';121 os << "===" << std::string(73, '-') << "===\n";122 123 // Print the total time followed by the section headers.124 os << llvm::format(" Total Execution Time: %.4f seconds\n\n", total.wall);125 if (total.user != total.wall)126 os << " ----User Time----";127 os << " ----Wall Time---- ----Name----\n";128 }129 130 void printFooter() override { os.flush(); }131 132 void printTime(const TimeRecord &time, const TimeRecord &total) override {133 if (total.user != total.wall) {134 os << llvm::format(" %8.4f (%5.1f%%)", time.user,135 100.0 * time.user / total.user);136 }137 os << llvm::format(" %8.4f (%5.1f%%) ", time.wall,138 100.0 * time.wall / total.wall);139 }140 141 void printListEntry(StringRef name, const TimeRecord &time,142 const TimeRecord &total, bool lastEntry) override {143 printTime(time, total);144 os << name << "\n";145 }146 147 void printTreeEntry(unsigned indent, StringRef name, const TimeRecord &time,148 const TimeRecord &total) override {149 printTime(time, total);150 os.indent(indent) << name << "\n";151 }152 153 void printTreeEntryEnd(unsigned indent, bool lastEntry) override {}154};155 156class OutputJsonStrategy : public OutputStrategy {157public:158 OutputJsonStrategy(raw_ostream &os) : OutputStrategy(os) {}159 160 void printHeader(const TimeRecord &total) override { os << "[" << "\n"; }161 162 void printFooter() override {163 os << "]" << "\n";164 os.flush();165 }166 167 void printTime(const TimeRecord &time, const TimeRecord &total) override {168 if (total.user != total.wall) {169 os << "\"user\": {";170 os << "\"duration\": " << llvm::format("%8.4f", time.user) << ", ";171 os << "\"percentage\": "172 << llvm::format("%5.1f", 100.0 * time.user / total.user);173 os << "}, ";174 }175 os << "\"wall\": {";176 os << "\"duration\": " << llvm::format("%8.4f", time.wall) << ", ";177 os << "\"percentage\": "178 << llvm::format("%5.1f", 100.0 * time.wall / total.wall);179 os << "}";180 }181 182 void printListEntry(StringRef name, const TimeRecord &time,183 const TimeRecord &total, bool lastEntry) override {184 os << "{";185 printTime(time, total);186 os << ", \"name\": " << "\"" << name << "\"";187 os << "}";188 if (!lastEntry)189 os << ",";190 os << "\n";191 }192 193 void printTreeEntry(unsigned indent, StringRef name, const TimeRecord &time,194 const TimeRecord &total) override {195 os.indent(indent) << "{";196 printTime(time, total);197 os << ", \"name\": " << "\"" << name << "\"";198 os << ", \"passes\": [" << "\n";199 }200 201 void printTreeEntryEnd(unsigned indent, bool lastEntry) override {202 os.indent(indent) << "{}]";203 os << "}";204 if (!lastEntry)205 os << ",";206 os << "\n";207 }208};209 210} // namespace211 212//===----------------------------------------------------------------------===//213// Timer Implementation for DefaultTimingManager214//===----------------------------------------------------------------------===//215 216namespace {217 218/// A timer used to sample execution time.219///220/// Separately tracks wall time and user time to account for parallel threads of221/// execution. Timers are intended to be started and stopped multiple times.222/// Each start and stop will add to the timer's wall and user time.223class TimerImpl {224public:225 using ChildrenMap = llvm::MapVector<const void *, std::unique_ptr<TimerImpl>>;226 using AsyncChildrenMap = llvm::DenseMap<uint64_t, ChildrenMap>;227 228 TimerImpl(std::string &&name, std::unique_ptr<OutputStrategy> &output)229 : threadId(llvm::get_threadid()), name(name), output(output) {}230 231 /// Start the timer.232 void start() { startTime = std::chrono::steady_clock::now(); }233 234 /// Stop the timer.235 void stop() {236 auto newTime = std::chrono::steady_clock::now() - startTime;237 wallTime += newTime;238 userTime += newTime;239 }240 241 /// Create a child timer nested within this one. Multiple calls to this242 /// function with the same unique identifier `id` will return the same child243 /// timer.244 ///245 /// This function can be called from other threads, as long as this timer246 /// outlives any uses of the child timer on the other thread.247 TimerImpl *nest(const void *id, function_ref<std::string()> nameBuilder) {248 auto tid = llvm::get_threadid();249 if (tid == threadId)250 return nestTail(children[id], nameBuilder);251 std::unique_lock<std::mutex> lock(asyncMutex);252 return nestTail(asyncChildren[tid][id], nameBuilder);253 }254 255 /// Tail-called from `nest()`.256 TimerImpl *nestTail(std::unique_ptr<TimerImpl> &child,257 function_ref<std::string()> nameBuilder) {258 if (!child)259 child = std::make_unique<TimerImpl>(nameBuilder(), output);260 return child.get();261 }262 263 /// Finalize this timer and all its children.264 ///265 /// If this timer has async children, which happens if `nest()` was called266 /// from another thread, this function merges the async childr timers into the267 /// main list of child timers.268 ///269 /// Caution: Call this function only after all nested timers running on other270 /// threads no longer need their timers!271 void finalize() {272 addAsyncUserTime();273 mergeAsyncChildren();274 }275 276 /// Add the user time of all async children to this timer's user time. This is277 /// necessary since the user time already contains all regular child timers,278 /// but not the asynchronous ones (by the nesting nature of the timers).279 std::chrono::nanoseconds addAsyncUserTime() {280 auto added = std::chrono::nanoseconds(0);281 for (auto &child : children)282 added += child.second->addAsyncUserTime();283 for (auto &thread : asyncChildren) {284 for (auto &child : thread.second) {285 child.second->addAsyncUserTime();286 added += child.second->userTime;287 }288 }289 userTime += added;290 return added;291 }292 293 /// Ensure that this timer and recursively all its children have their async294 /// children folded into the main map of children.295 void mergeAsyncChildren() {296 for (auto &child : children)297 child.second->mergeAsyncChildren();298 mergeChildren(std::move(asyncChildren));299 assert(asyncChildren.empty());300 }301 302 /// Merge multiple child timers into this timer.303 ///304 /// Children in `other` are added as children to this timer, or, if this timer305 /// already contains a child with the corresponding unique identifier, are306 /// merged into the existing child.307 void mergeChildren(ChildrenMap &&other) {308 if (children.empty()) {309 children = std::move(other);310 for (auto &child : children)311 child.second->mergeAsyncChildren();312 } else {313 for (auto &child : other)314 mergeChild(child.first, std::move(child.second));315 other.clear();316 }317 }318 319 /// See above.320 void mergeChildren(AsyncChildrenMap &&other) {321 for (auto &thread : other) {322 mergeChildren(std::move(thread.second));323 }324 other.clear();325 }326 327 /// Merge a child timer into this timer for a given unique identifier.328 ///329 /// Moves all child and async child timers of `other` into this timer's child330 /// for the given unique identifier.331 void mergeChild(const void *id, std::unique_ptr<TimerImpl> &&other) {332 auto &into = children[id];333 if (!into) {334 into = std::move(other);335 into->mergeAsyncChildren();336 } else {337 into->wallTime = std::max(into->wallTime, other->wallTime);338 into->userTime += other->userTime;339 into->mergeChildren(std::move(other->children));340 into->mergeChildren(std::move(other->asyncChildren));341 other.reset();342 }343 }344 345 /// Dump a human-readable tree representation of the timer and its children.346 /// This is useful for debugging the timing mechanisms and structure of the347 /// timers.348 void dump(raw_ostream &os, unsigned indent = 0, unsigned markThreadId = 0) {349 auto time = getTimeRecord();350 os << std::string(indent * 2, ' ') << name << " [" << threadId << "]"351 << llvm::format(" %7.4f / %7.4f", time.user, time.wall);352 if (threadId != markThreadId && markThreadId != 0)353 os << " (*)";354 os << "\n";355 for (auto &child : children)356 child.second->dump(os, indent + 1, threadId);357 for (auto &thread : asyncChildren)358 for (auto &child : thread.second)359 child.second->dump(os, indent + 1, threadId);360 }361 362 /// Returns the time for this timer in seconds.363 TimeRecord getTimeRecord() {364 return TimeRecord(365 std::chrono::duration_cast<std::chrono::duration<double>>(wallTime)366 .count(),367 std::chrono::duration_cast<std::chrono::duration<double>>(userTime)368 .count());369 }370 371 /// Print the timing result in list mode.372 void printAsList(TimeRecord total) {373 // Flatten the leaf timers in the tree and merge them by name.374 llvm::StringMap<TimeRecord> mergedTimers;375 std::function<void(TimerImpl *)> addTimer = [&](TimerImpl *timer) {376 mergedTimers[timer->name] += timer->getTimeRecord();377 for (auto &children : timer->children)378 addTimer(children.second.get());379 };380 addTimer(this);381 382 // Sort the timing information by wall time.383 std::vector<std::pair<StringRef, TimeRecord>> timerNameAndTime;384 for (auto &it : mergedTimers)385 timerNameAndTime.emplace_back(it.first(), it.second);386 llvm::array_pod_sort(timerNameAndTime.begin(), timerNameAndTime.end(),387 [](const std::pair<StringRef, TimeRecord> *lhs,388 const std::pair<StringRef, TimeRecord> *rhs) {389 return llvm::array_pod_sort_comparator<double>(390 &rhs->second.wall, &lhs->second.wall);391 });392 393 // Print the timing information sequentially.394 for (auto &timeData : timerNameAndTime)395 output->printListEntry(timeData.first, timeData.second, total);396 }397 398 /// Print the timing result in tree mode.399 void printAsTree(TimeRecord total, unsigned indent = 0) {400 unsigned childIndent = indent;401 if (!hidden) {402 output->printTreeEntry(indent, name, getTimeRecord(), total);403 childIndent += 2;404 }405 for (auto &child : children) {406 child.second->printAsTree(total, childIndent);407 }408 if (!hidden) {409 output->printTreeEntryEnd(indent);410 }411 }412 413 /// Print the current timing information.414 void print(DisplayMode displayMode) {415 // Print the banner.416 auto total = getTimeRecord();417 output->printHeader(total);418 419 // Defer to a specialized printer for each display mode.420 switch (displayMode) {421 case DisplayMode::List:422 printAsList(total);423 break;424 case DisplayMode::Tree:425 printAsTree(total);426 break;427 }428 429 // Print the top-level time not accounted for by child timers, and the430 // total.431 auto rest = total;432 for (auto &child : children)433 rest -= child.second->getTimeRecord();434 output->printListEntry("Rest", rest, total);435 output->printListEntry("Total", total, total, /*lastEntry=*/true);436 output->printFooter();437 }438 439 /// The last time instant at which the timer was started.440 std::chrono::time_point<std::chrono::steady_clock> startTime;441 442 /// Accumulated wall time. If multiple threads of execution are merged into443 /// this timer, the wall time will hold the maximum wall time of each thread444 /// of execution.445 std::chrono::nanoseconds wallTime = std::chrono::nanoseconds(0);446 447 /// Accumulated user time. If multiple threads of execution are merged into448 /// this timer, each thread's user time is added here.449 std::chrono::nanoseconds userTime = std::chrono::nanoseconds(0);450 451 /// The thread on which this timer is running.452 uint64_t threadId;453 454 /// A descriptive name for this timer.455 std::string name;456 457 /// Whether to omit this timer from reports and directly show its children.458 bool hidden = false;459 460 /// Child timers on the same thread the timer itself. We keep at most one461 /// timer per unique identifier.462 ChildrenMap children;463 464 /// Child timers on other threads. We keep at most one timer per unique465 /// identifier.466 AsyncChildrenMap asyncChildren;467 468 /// Mutex for the async children.469 std::mutex asyncMutex;470 471 std::unique_ptr<OutputStrategy> &output;472};473 474} // namespace475 476//===----------------------------------------------------------------------===//477// DefaultTimingManager478//===----------------------------------------------------------------------===//479 480namespace mlir {481namespace detail {482 483/// Implementation details of the `DefaultTimingManager`.484class DefaultTimingManagerImpl {485public:486 /// Whether we should do our work or not.487 bool enabled = false;488 489 /// The configured display mode.490 DisplayMode displayMode = DisplayMode::Tree;491 492 /// The root timer.493 std::unique_ptr<TimerImpl> rootTimer;494};495 496} // namespace detail497} // namespace mlir498 499DefaultTimingManager::DefaultTimingManager()500 : impl(std::make_unique<DefaultTimingManagerImpl>()),501 out(std::make_unique<OutputTextStrategy>(llvm::errs())) {502 clear(); // initializes the root timer503}504 505DefaultTimingManager::~DefaultTimingManager() { print(); }506 507/// Enable or disable execution time sampling.508void DefaultTimingManager::setEnabled(bool enabled) { impl->enabled = enabled; }509 510/// Return whether execution time sampling is enabled.511bool DefaultTimingManager::isEnabled() const { return impl->enabled; }512 513/// Change the display mode.514void DefaultTimingManager::setDisplayMode(DisplayMode displayMode) {515 impl->displayMode = displayMode;516}517 518/// Return the current display mode;519DefaultTimingManager::DisplayMode DefaultTimingManager::getDisplayMode() const {520 return impl->displayMode;521}522 523/// Change the stream where the output will be printed to.524void DefaultTimingManager::setOutput(std::unique_ptr<OutputStrategy> output) {525 out = std::move(output);526}527 528/// Print and clear the timing results.529void DefaultTimingManager::print() {530 if (impl->enabled) {531 impl->rootTimer->finalize();532 impl->rootTimer->print(impl->displayMode);533 }534 clear();535}536 537/// Clear the timing results.538void DefaultTimingManager::clear() {539 impl->rootTimer = std::make_unique<TimerImpl>("root", out);540 impl->rootTimer->hidden = true;541}542 543/// Debug print the timer data structures to an output stream.544void DefaultTimingManager::dumpTimers(raw_ostream &os) {545 impl->rootTimer->dump(os);546}547 548/// Debug print the timers as a list.549void DefaultTimingManager::dumpAsList(raw_ostream &os) {550 impl->rootTimer->finalize();551 impl->rootTimer->print(DisplayMode::List);552}553 554/// Debug print the timers as a tree.555void DefaultTimingManager::dumpAsTree(raw_ostream &os) {556 impl->rootTimer->finalize();557 impl->rootTimer->print(DisplayMode::Tree);558}559 560std::optional<void *> DefaultTimingManager::rootTimer() {561 if (impl->enabled)562 return impl->rootTimer.get();563 return std::nullopt;564}565 566void DefaultTimingManager::startTimer(void *handle) {567 static_cast<TimerImpl *>(handle)->start();568}569 570void DefaultTimingManager::stopTimer(void *handle) {571 static_cast<TimerImpl *>(handle)->stop();572}573 574void *DefaultTimingManager::nestTimer(void *handle, const void *id,575 function_ref<std::string()> nameBuilder) {576 return static_cast<TimerImpl *>(handle)->nest(id, nameBuilder);577}578 579void DefaultTimingManager::hideTimer(void *handle) {580 static_cast<TimerImpl *>(handle)->hidden = true;581}582 583//===----------------------------------------------------------------------===//584// DefaultTimingManager Command Line Options585//===----------------------------------------------------------------------===//586 587namespace {588struct DefaultTimingManagerOptions {589 llvm::cl::opt<bool> timing{"mlir-timing",590 llvm::cl::desc("Display execution times"),591 llvm::cl::init(false)};592 llvm::cl::opt<DisplayMode> displayMode{593 "mlir-timing-display", llvm::cl::desc("Display method for timing data"),594 llvm::cl::init(DisplayMode::Tree),595 llvm::cl::values(596 clEnumValN(DisplayMode::List, "list",597 "display the results in a list sorted by total time"),598 clEnumValN(DisplayMode::Tree, "tree",599 "display the results ina with a nested tree view"))};600 llvm::cl::opt<OutputFormat> outputFormat{601 "mlir-output-format", llvm::cl::desc("Output format for timing data"),602 llvm::cl::init(OutputFormat::Text),603 llvm::cl::values(clEnumValN(OutputFormat::Text, "text",604 "display the results in text format"),605 clEnumValN(OutputFormat::Json, "json",606 "display the results in JSON format"))};607};608} // namespace609 610static llvm::ManagedStatic<DefaultTimingManagerOptions> options;611 612void mlir::registerDefaultTimingManagerCLOptions() {613 // Make sure that the options struct has been constructed.614 *options;615}616 617void mlir::applyDefaultTimingManagerCLOptions(DefaultTimingManager &tm) {618 if (!options.isConstructed())619 return;620 tm.setEnabled(options->timing);621 tm.setDisplayMode(options->displayMode);622 tm.setOutput(createOutputStrategy(options->outputFormat, llvm::errs()));623}624 625std::unique_ptr<OutputStrategy>626mlir::createOutputStrategy(DefaultTimingManager::OutputFormat fmt,627 raw_ostream &os) {628 switch (fmt) {629 case OutputFormat::Text:630 return std::make_unique<OutputTextStrategy>(os);631 case OutputFormat::Json:632 return std::make_unique<OutputJsonStrategy>(os);633 }634 llvm_unreachable("Invalid output format");635}636