[llvm] r357340 - Adds `-ftime-trace` option to clang that produces Chrome `chrome://tracing` compatible JSON profiling output dumps.
Anton Afanasyev via llvm-commits
llvm-commits at lists.llvm.org
Sat Mar 30 01:42:48 PDT 2019
Author: anton-afanasyev
Date: Sat Mar 30 01:42:48 2019
New Revision: 357340
URL: http://llvm.org/viewvc/llvm-project?rev=357340&view=rev
Log:
Adds `-ftime-trace` option to clang that produces Chrome `chrome://tracing` compatible JSON profiling output dumps.
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
Added:
llvm/trunk/include/llvm/Support/TimeProfiler.h
llvm/trunk/lib/Support/TimeProfiler.cpp
Modified:
llvm/trunk/lib/IR/LegacyPassManager.cpp
llvm/trunk/lib/Support/CMakeLists.txt
Added: llvm/trunk/include/llvm/Support/TimeProfiler.h
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/include/llvm/Support/TimeProfiler.h?rev=357340&view=auto
==============================================================================
--- llvm/trunk/include/llvm/Support/TimeProfiler.h (added)
+++ llvm/trunk/include/llvm/Support/TimeProfiler.h Sat Mar 30 01:42:48 2019
@@ -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<raw_pwrite_stream> &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<std::string()> 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<std::string()> Detail) {
+ if (TimeTraceProfilerInstance != nullptr)
+ timeTraceProfilerBegin(Name, Detail);
+ }
+ ~TimeTraceScope() {
+ if (TimeTraceProfilerInstance != nullptr)
+ timeTraceProfilerEnd();
+ }
+};
+
+} // end namespace llvm
+
+#endif
Modified: llvm/trunk/lib/IR/LegacyPassManager.cpp
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/lib/IR/LegacyPassManager.cpp?rev=357340&r1=357339&r2=357340&view=diff
==============================================================================
--- llvm/trunk/lib/IR/LegacyPassManager.cpp (original)
+++ llvm/trunk/lib/IR/LegacyPassManager.cpp Sat Mar 30 01:42:48 2019
@@ -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 <algorithm>
@@ -1628,6 +1629,10 @@ bool FPPassManager::runOnFunction(Functi
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(Functi
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(Modul
/// 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
Modified: llvm/trunk/lib/Support/CMakeLists.txt
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/lib/Support/CMakeLists.txt?rev=357340&r1=357339&r2=357340&view=diff
==============================================================================
--- llvm/trunk/lib/Support/CMakeLists.txt (original)
+++ llvm/trunk/lib/Support/CMakeLists.txt Sat Mar 30 01:42:48 2019
@@ -139,6 +139,7 @@ add_llvm_library(LLVMSupport
TarWriter.cpp
TargetParser.cpp
ThreadPool.cpp
+ TimeProfiler.cpp
Timer.cpp
ToolOutputFile.cpp
TrigramIndex.cpp
Added: llvm/trunk/lib/Support/TimeProfiler.cpp
URL: http://llvm.org/viewvc/llvm-project/llvm/trunk/lib/Support/TimeProfiler.cpp?rev=357340&view=auto
==============================================================================
--- llvm/trunk/lib/Support/TimeProfiler.cpp (added)
+++ llvm/trunk/lib/Support/TimeProfiler.cpp Sat Mar 30 01:42:48 2019
@@ -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 <cassert>
+#include <chrono>
+#include <string>
+#include <unordered_map>
+#include <vector>
+
+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<steady_clock::rep, steady_clock::period> DurationType;
+typedef std::pair<std::string, DurationType> NameAndDuration;
+
+struct Entry {
+ time_point<steady_clock> 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<std::string()> 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<microseconds>(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<raw_pwrite_stream> &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<microseconds>(E.Start - StartTime).count();
+ auto DurUs = duration_cast<microseconds>(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<NameAndDuration> 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<microseconds>(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<Entry> Stack;
+ std::vector<Entry> Entries;
+ std::unordered_map<std::string, DurationType> TotalPerName;
+ std::unordered_map<std::string, size_t> CountPerName;
+ time_point<steady_clock> 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<raw_pwrite_stream> &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<std::string()> Detail) {
+ if (TimeTraceProfilerInstance != nullptr)
+ TimeTraceProfilerInstance->begin(Name, Detail);
+}
+
+void timeTraceProfilerEnd() {
+ if (TimeTraceProfilerInstance != nullptr)
+ TimeTraceProfilerInstance->end();
+}
+
+} // namespace llvm
More information about the llvm-commits
mailing list