70 changes: 70 additions & 0 deletions llvm/include/llvm/Support/TimeProfiler.h
View file
Original file line number Diff line number Diff line change
@@ -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
12 changes: 12 additions & 0 deletions llvm/lib/IR/LegacyPassManager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -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
Expand Down
1 change: 1 addition & 0 deletions llvm/lib/Support/CMakeLists.txt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -139,6 +139,7 @@ add_llvm_library(LLVMSupport
TarWriter.cpp
TargetParser.cpp
ThreadPool.cpp
TimeProfiler.cpp
Timer.cpp
ToolOutputFile.cpp
TrigramIndex.cpp
Expand Down
184 changes: 184 additions & 0 deletions llvm/lib/Support/TimeProfiler.cpp
View file
Original file line number Diff line number Diff line change
@@ -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