From e6ea17a9ceba2bbfc2005f9eb320974051f36c11 Mon Sep 17 00:00:00 2001 From: Anton Afanasyev Date: Sat, 30 Mar 2019 08:42:48 +0000 Subject: [PATCH] Adds `-ftime-trace` option to clang that produces Chrome `chrome://tracing` compatible JSON profiling output dumps. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This change adds hierarchical "time trace" profiling blocks that can be visualized in Chrome, in a "flame chart" style. Each profiling block can have a "detail" string that for example indicates the file being processed, template name being instantiated, function being optimized etc. This is taken from GitHub PR: https://github.com/aras-p/llvm-project-20170507/pull/2 Patch by Aras Pranckevičius. Differential Revision: https://reviews.llvm.org/D58675 llvm-svn: 357340 --- include/llvm/Support/TimeProfiler.h | 70 +++++++++++ lib/IR/LegacyPassManager.cpp | 12 ++ lib/Support/CMakeLists.txt | 1 + lib/Support/TimeProfiler.cpp | 184 ++++++++++++++++++++++++++++ 4 files changed, 267 insertions(+) create mode 100644 include/llvm/Support/TimeProfiler.h create mode 100644 lib/Support/TimeProfiler.cpp diff --git a/include/llvm/Support/TimeProfiler.h b/include/llvm/Support/TimeProfiler.h new file mode 100644 index 00000000000..ae6703e2169 --- /dev/null +++ b/include/llvm/Support/TimeProfiler.h @@ -0,0 +1,70 @@ +//===- llvm/Support/TimeProfiler.h - Hierarchical Time Profiler -*- C++ -*-===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#ifndef LLVM_SUPPORT_TIME_PROFILER_H +#define LLVM_SUPPORT_TIME_PROFILER_H + +#include "llvm/Support/raw_ostream.h" + +namespace llvm { + +struct TimeTraceProfiler; +extern TimeTraceProfiler *TimeTraceProfilerInstance; + +/// Initialize the time trace profiler. +/// This sets up the global \p TimeTraceProfilerInstance +/// variable to be the profiler instance. +void timeTraceProfilerInitialize(); + +/// Cleanup the time trace profiler, if it was initialized. +void timeTraceProfilerCleanup(); + +/// Is the time trace profiler enabled, i.e. initialized? +inline bool timeTraceProfilerEnabled() { + return TimeTraceProfilerInstance != nullptr; +} + +/// Write profiling data to output file. +/// Data produced is JSON, in Chrome "Trace Event" format, see +/// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview +void timeTraceProfilerWrite(std::unique_ptr &OS); + +/// Manually begin a time section, with the given \p Name and \p Detail. +/// Profiler copies the string data, so the pointers can be given into +/// temporaries. Time sections can be hierarchical; every Begin must have a +/// matching End pair but they can nest. +void timeTraceProfilerBegin(StringRef Name, StringRef Detail); +void timeTraceProfilerBegin(StringRef Name, + llvm::function_ref Detail); + +/// Manually end the last time section. +void timeTraceProfilerEnd(); + +/// The TimeTraceScope is a helper class to call the begin and end functions +/// of the time trace profiler. When the object is constructed, it begins +/// the section; and when it is destroyed, it stops it. If the time profiler +/// is not initialized, the overhead is a single branch. +struct TimeTraceScope { + TimeTraceScope(StringRef Name, StringRef Detail) { + if (TimeTraceProfilerInstance != nullptr) + timeTraceProfilerBegin(Name, Detail); + } + TimeTraceScope(StringRef Name, llvm::function_ref Detail) { + if (TimeTraceProfilerInstance != nullptr) + timeTraceProfilerBegin(Name, Detail); + } + ~TimeTraceScope() { + if (TimeTraceProfilerInstance != nullptr) + timeTraceProfilerEnd(); + } +}; + +} // end namespace llvm + +#endif diff --git a/lib/IR/LegacyPassManager.cpp b/lib/IR/LegacyPassManager.cpp index 98b7d9b76aa..e2717f7887e 100644 --- a/lib/IR/LegacyPassManager.cpp +++ b/lib/IR/LegacyPassManager.cpp @@ -27,6 +27,7 @@ #include "llvm/Support/ErrorHandling.h" #include "llvm/Support/ManagedStatic.h" #include "llvm/Support/Mutex.h" +#include "llvm/Support/TimeProfiler.h" #include "llvm/Support/Timer.h" #include "llvm/Support/raw_ostream.h" #include @@ -1628,6 +1629,10 @@ bool FPPassManager::runOnFunction(Function &F) { FunctionSize = F.getInstructionCount(); } + bool ProfileTime = llvm::timeTraceProfilerEnabled(); + if (ProfileTime) + llvm::timeTraceProfilerBegin("OptFunction", F.getName()); + for (unsigned Index = 0; Index < getNumContainedPasses(); ++Index) { FunctionPass *FP = getContainedPass(Index); bool LocalChanged = false; @@ -1668,12 +1673,17 @@ bool FPPassManager::runOnFunction(Function &F) { recordAvailableAnalysis(FP); removeDeadPasses(FP, F.getName(), ON_FUNCTION_MSG); } + + if (ProfileTime) + llvm::timeTraceProfilerEnd(); + return Changed; } bool FPPassManager::runOnModule(Module &M) { bool Changed = false; + llvm::TimeTraceScope TimeScope("OptModule", M.getName()); for (Function &F : M) Changed |= runOnFunction(F); @@ -1706,6 +1716,8 @@ bool FPPassManager::doFinalization(Module &M) { /// the module, and if so, return true. bool MPPassManager::runOnModule(Module &M) { + llvm::TimeTraceScope TimeScope("OptModule", M.getName()); + bool Changed = false; // Initialize on-the-fly passes diff --git a/lib/Support/CMakeLists.txt b/lib/Support/CMakeLists.txt index b5246b27ca1..c5846ad6c81 100644 --- a/lib/Support/CMakeLists.txt +++ b/lib/Support/CMakeLists.txt @@ -139,6 +139,7 @@ add_llvm_library(LLVMSupport TarWriter.cpp TargetParser.cpp ThreadPool.cpp + TimeProfiler.cpp Timer.cpp ToolOutputFile.cpp TrigramIndex.cpp diff --git a/lib/Support/TimeProfiler.cpp b/lib/Support/TimeProfiler.cpp new file mode 100644 index 00000000000..6b999cad71a --- /dev/null +++ b/lib/Support/TimeProfiler.cpp @@ -0,0 +1,184 @@ +//===-- TimeProfiler.cpp - Hierarchical Time Profiler ---------------------===// +// +// The LLVM Compiler Infrastructure +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// +// +/// \file Hierarchical time profiler implementation. +// +//===----------------------------------------------------------------------===// + +#include "llvm/Support/TimeProfiler.h" +#include "llvm/ADT/StringExtras.h" +#include "llvm/Support/FileSystem.h" +#include +#include +#include +#include +#include + +using namespace std::chrono; + +namespace llvm { + +TimeTraceProfiler *TimeTraceProfilerInstance = nullptr; + +static std::string escapeString(StringRef Src) { + std::string OS; + for (const unsigned char &C : Src) { + switch (C) { + case '"': + case '/': + case '\\': + case '\b': + case '\f': + case '\n': + case '\r': + case '\t': + OS += '\\'; + OS += C; + break; + default: + if (isPrint(C)) { + OS += C; + } + } + } + return OS; +} + +typedef duration DurationType; +typedef std::pair NameAndDuration; + +struct Entry { + time_point Start; + DurationType Duration; + std::string Name; + std::string Detail; +}; + +struct TimeTraceProfiler { + TimeTraceProfiler() { + Stack.reserve(8); + Entries.reserve(128); + StartTime = steady_clock::now(); + } + + void begin(std::string Name, llvm::function_ref Detail) { + Entry E = {steady_clock::now(), {}, Name, Detail()}; + Stack.push_back(std::move(E)); + } + + void end() { + assert(!Stack.empty() && "Must call begin() first"); + auto &E = Stack.back(); + E.Duration = steady_clock::now() - E.Start; + + // Only include sections longer than 500us. + if (duration_cast(E.Duration).count() > 500) + Entries.emplace_back(E); + + // Track total time taken by each "name", but only the topmost levels of + // them; e.g. if there's a template instantiation that instantiates other + // templates from within, we only want to add the topmost one. "topmost" + // happens to be the ones that don't have any currently open entries above + // itself. + if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) { + return Val.Name == E.Name; + }) == Stack.rend()) { + TotalPerName[E.Name] += E.Duration; + CountPerName[E.Name]++; + } + + Stack.pop_back(); + } + + void Write(std::unique_ptr &OS) { + assert(Stack.empty() && + "All profiler sections should be ended when calling Write"); + + *OS << "{ \"traceEvents\": [\n"; + + // Emit all events for the main flame graph. + for (const auto &E : Entries) { + auto StartUs = duration_cast(E.Start - StartTime).count(); + auto DurUs = duration_cast(E.Duration).count(); + *OS << "{ \"pid\":1, \"tid\":0, \"ph\":\"X\", \"ts\":" << StartUs + << ", \"dur\":" << DurUs << ", \"name\":\"" << escapeString(E.Name) + << "\", \"args\":{ \"detail\":\"" << escapeString(E.Detail) + << "\"} },\n"; + } + + // Emit totals by section name as additional "thread" events, sorted from + // longest one. + int Tid = 1; + std::vector SortedTotals; + SortedTotals.reserve(TotalPerName.size()); + for (const auto &E : TotalPerName) { + SortedTotals.push_back(E); + } + std::sort(SortedTotals.begin(), SortedTotals.end(), + [](const NameAndDuration &A, const NameAndDuration &B) { + return A.second > B.second; + }); + for (const auto &E : SortedTotals) { + auto DurUs = duration_cast(E.second).count(); + *OS << "{ \"pid\":1, \"tid\":" << Tid << ", \"ph\":\"X\", \"ts\":" << 0 + << ", \"dur\":" << DurUs << ", \"name\":\"Total " + << escapeString(E.first) + << "\", \"args\":{ \"count\":" << CountPerName[E.first] + << ", \"avg ms\":" << (DurUs / CountPerName[E.first] / 1000) + << "} },\n"; + ++Tid; + } + + // Emit metadata event with process name. + *OS << "{ \"cat\":\"\", \"pid\":1, \"tid\":0, \"ts\":0, \"ph\":\"M\", " + "\"name\":\"process_name\", \"args\":{ \"name\":\"clang\" } }\n"; + *OS << "] }\n"; + } + + std::vector Stack; + std::vector Entries; + std::unordered_map TotalPerName; + std::unordered_map CountPerName; + time_point StartTime; +}; + +void timeTraceProfilerInitialize() { + assert(TimeTraceProfilerInstance == nullptr && + "Profiler should not be initialized"); + TimeTraceProfilerInstance = new TimeTraceProfiler(); +} + +void timeTraceProfilerCleanup() { + delete TimeTraceProfilerInstance; + TimeTraceProfilerInstance = nullptr; +} + +void timeTraceProfilerWrite(std::unique_ptr &OS) { + assert(TimeTraceProfilerInstance != nullptr && + "Profiler object can't be null"); + TimeTraceProfilerInstance->Write(OS); +} + +void timeTraceProfilerBegin(StringRef Name, StringRef Detail) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->begin(Name, [&]() { return Detail; }); +} + +void timeTraceProfilerBegin(StringRef Name, + llvm::function_ref Detail) { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->begin(Name, Detail); +} + +void timeTraceProfilerEnd() { + if (TimeTraceProfilerInstance != nullptr) + TimeTraceProfilerInstance->end(); +} + +} // namespace llvm