Index: lld/COFF/Config.h =================================================================== --- lld/COFF/Config.h +++ lld/COFF/Config.h @@ -90,6 +90,7 @@ bool Debug = false; bool DebugDwarf = false; bool DebugGHashes = false; + bool ShowTiming = false; unsigned DebugTypes = static_cast(DebugType::None); llvm::SmallString<128> PDBPath; std::vector Argv; Index: lld/COFF/Driver.cpp =================================================================== --- lld/COFF/Driver.cpp +++ lld/COFF/Driver.cpp @@ -17,6 +17,7 @@ #include "lld/Common/Driver.h" #include "lld/Common/ErrorHandler.h" #include "lld/Common/Memory.h" +#include "lld/Common/Timer.h" #include "lld/Common/Version.h" #include "llvm/ADT/Optional.h" #include "llvm/ADT/StringSwitch.h" @@ -47,6 +48,8 @@ namespace lld { namespace coff { +static Timer InputFileTimer("Input File Reading", Timer::root()); + Configuration *Config; LinkerDriver *Driver; @@ -714,6 +717,8 @@ } bool LinkerDriver::run() { + ScopedTimer T(InputFileTimer); + bool DidWork = !TaskQueue.empty(); while (!TaskQueue.empty()) { TaskQueue.front()(); @@ -765,6 +770,10 @@ return; } + if (Args.hasArg(OPT_show_timing)) + Config->ShowTiming = true; + + ScopedTimer T(Timer::root()); // Handle --version, which is an lld extension. This option is a bit odd // because it doesn't start with "/", but we deliberately chose "--" to // avoid conflict with /version and for compatibility with clang-cl. @@ -1331,6 +1340,10 @@ // Write the result. writeResult(); + + // Stop early so we can print the results. + Timer::root().stop(); + Timer::root().print(); } } // namespace coff Index: lld/COFF/ICF.cpp =================================================================== --- lld/COFF/ICF.cpp +++ lld/COFF/ICF.cpp @@ -21,6 +21,7 @@ #include "Chunks.h" #include "Symbols.h" #include "lld/Common/ErrorHandler.h" +#include "lld/Common/Timer.h" #include "llvm/ADT/Hashing.h" #include "llvm/Support/Debug.h" #include "llvm/Support/Parallel.h" @@ -34,6 +35,8 @@ namespace lld { namespace coff { +static Timer ICFTimer("ICF", Timer::root()); + class ICF { public: void run(ArrayRef V); @@ -207,6 +210,8 @@ // Two sections are considered the same if their section headers, // contents and relocations are all the same. void ICF::run(ArrayRef Vec) { + ScopedTimer T(ICFTimer); + // Collect only mergeable sections and group by hash value. uint32_t NextId = 1; for (Chunk *C : Vec) { Index: lld/COFF/MarkLive.cpp =================================================================== --- lld/COFF/MarkLive.cpp +++ lld/COFF/MarkLive.cpp @@ -9,16 +9,21 @@ #include "Chunks.h" #include "Symbols.h" +#include "lld/Common/Timer.h" #include "llvm/ADT/STLExtras.h" #include namespace lld { namespace coff { +static Timer GCTimer("GC", Timer::root()); + // Set live bit on for each reachable chunk. Unmarked (unreachable) // COMDAT chunks will be ignored by Writer, so they will be excluded // from the final output. void markLive(ArrayRef Chunks) { + ScopedTimer T(GCTimer); + // We build up a worklist of sections which have been marked as live. We only // push into the worklist when we discover an unmarked section, and we mark // as we push, so sections never appear twice in the list. Index: lld/COFF/Options.td =================================================================== --- lld/COFF/Options.td +++ lld/COFF/Options.td @@ -132,6 +132,7 @@ // Flags for debugging def lldmap : F<"lldmap">; def lldmap_file : Joined<["/", "-"], "lldmap:">; +def show_timing : F<"time">; //============================================================================== // The flags below do nothing. They are defined only for link.exe compatibility. Index: lld/COFF/PDB.cpp =================================================================== --- lld/COFF/PDB.cpp +++ lld/COFF/PDB.cpp @@ -15,6 +15,7 @@ #include "Symbols.h" #include "Writer.h" #include "lld/Common/ErrorHandler.h" +#include "lld/Common/Timer.h" #include "llvm/DebugInfo/CodeView/CVDebugRecord.h" #include "llvm/DebugInfo/CodeView/DebugSubsectionRecord.h" #include "llvm/DebugInfo/CodeView/GlobalTypeTableBuilder.h" @@ -62,6 +63,15 @@ static ExitOnError ExitOnErr; +static Timer TotalPdbLinkTimer("PDB Emission (Cumulative)", Timer::root()); + +static Timer AddObjectsTimer("Add Objects", TotalPdbLinkTimer); +static Timer TypeMergingTimer("Type Merging", AddObjectsTimer); +static Timer SymbolMergingTimer("Symbol Merging", AddObjectsTimer); +static Timer GlobalsLayoutTimer("Globals Stream Layout", TotalPdbLinkTimer); +static Timer TpiStreamLayoutTimer("TPI Stream Layout", TotalPdbLinkTimer); +static Timer DiskCommitTimer("Commit to Disk", TotalPdbLinkTimer); + namespace { /// Map from type index and item index in a type server PDB to the /// corresponding index in the destination PDB. @@ -233,6 +243,8 @@ const CVIndexMap &PDBLinker::mergeDebugT(ObjFile *File, CVIndexMap &ObjectIndexMap) { + ScopedTimer T(TypeMergingTimer); + ArrayRef Data = getDebugSection(File, ".debug$T"); if (Data.empty()) return ObjectIndexMap; @@ -747,6 +759,8 @@ CVIndexMap ObjectIndexMap; const CVIndexMap &IndexMap = mergeDebugT(File, ObjectIndexMap); + ScopedTimer T(SymbolMergingTimer); + // Now do all live .debug$S sections. DebugStringTableSubsectionRef CVStrTab; DebugChecksumsSubsectionRef Checksums; @@ -864,12 +878,15 @@ // Add all object files to the PDB. Merge .debug$T sections into IpiData and // TpiData. void PDBLinker::addObjectsToPDB() { + ScopedTimer T1(AddObjectsTimer); for (ObjFile *File : ObjFile::Instances) addObjFile(File); Builder.getStringTableBuilder().setStrings(PDBStrTab); + T1.stop(); // Construct TPI and IPI stream contents. + ScopedTimer T2(TpiStreamLayoutTimer); if (Config->DebugGHashes) { addTypeInfo(Builder.getTpiBuilder(), GlobalTypeTable); addTypeInfo(Builder.getIpiBuilder(), GlobalIDTable); @@ -877,7 +894,9 @@ addTypeInfo(Builder.getTpiBuilder(), TypeTable); addTypeInfo(Builder.getIpiBuilder(), IDTable); } + T2.stop(); + ScopedTimer T3(GlobalsLayoutTimer); // Compute the public and global symbols. auto &GsiBuilder = Builder.getGsiBuilder(); std::vector Publics; @@ -974,10 +993,13 @@ ArrayRef OutputSections, ArrayRef SectionTable, const llvm::codeview::DebugInfo &BuildId) { + ScopedTimer T1(TotalPdbLinkTimer); PDBLinker PDB(Symtab); PDB.initialize(BuildId); PDB.addObjectsToPDB(); PDB.addSections(OutputSections, SectionTable); + + ScopedTimer T2(DiskCommitTimer); PDB.commit(); } Index: lld/COFF/SymbolTable.cpp =================================================================== --- lld/COFF/SymbolTable.cpp +++ lld/COFF/SymbolTable.cpp @@ -14,6 +14,7 @@ #include "Symbols.h" #include "lld/Common/ErrorHandler.h" #include "lld/Common/Memory.h" +#include "lld/Common/Timer.h" #include "llvm/IR/LLVMContext.h" #include "llvm/Support/Debug.h" #include "llvm/Support/raw_ostream.h" @@ -24,6 +25,8 @@ namespace lld { namespace coff { +static Timer LTOTimer("LTO", Timer::root()); + SymbolTable *Symtab; void SymbolTable::addFile(InputFile *File) { @@ -384,6 +387,8 @@ void SymbolTable::addCombinedLTOObjects() { if (BitcodeFile::Instances.empty()) return; + + ScopedTimer T(LTOTimer); for (StringRef Object : compileBitcodeFiles()) { auto *Obj = make(MemoryBufferRef(Object, "lto.tmp")); Obj->parse(); Index: lld/COFF/Writer.h =================================================================== --- lld/COFF/Writer.h +++ lld/COFF/Writer.h @@ -13,6 +13,7 @@ #include "Chunks.h" #include "llvm/ADT/StringRef.h" #include "llvm/Object/COFF.h" +#include #include #include Index: lld/COFF/Writer.cpp =================================================================== --- lld/COFF/Writer.cpp +++ lld/COFF/Writer.cpp @@ -17,6 +17,7 @@ #include "Symbols.h" #include "lld/Common/ErrorHandler.h" #include "lld/Common/Memory.h" +#include "lld/Common/Timer.h" #include "llvm/ADT/DenseMap.h" #include "llvm/ADT/STLExtras.h" #include "llvm/ADT/StringSwitch.h" @@ -163,6 +164,9 @@ namespace lld { namespace coff { +static Timer CodeLayoutTimer("Code Layout", Timer::root()); +static Timer DiskCommitTimer("Commit Output File", Timer::root()); + void writeResult() { Writer().run(); } void OutputSection::setRVA(uint64_t RVA) { @@ -284,6 +288,8 @@ // The main function of the writer. void Writer::run() { + ScopedTimer T1(CodeLayoutTimer); + createSections(); createMiscChunks(); createImportTables(); @@ -308,14 +314,16 @@ sortExceptionTable(); writeBuildId(); - if (!Config->PDBPath.empty() && Config->Debug) { + T1.stop(); + if (!Config->PDBPath.empty() && Config->Debug) { assert(BuildId); createPDB(Symtab, OutputSections, SectionTable, *BuildId->BuildId); } writeMapFile(OutputSections); + ScopedTimer T2(DiskCommitTimer); if (auto E = Buffer->commit()) fatal("failed to write the output file: " + toString(std::move(E))); } Index: lld/Common/CMakeLists.txt =================================================================== --- lld/Common/CMakeLists.txt +++ lld/Common/CMakeLists.txt @@ -10,6 +10,7 @@ Strings.cpp TargetOptionsCommandFlags.cpp Threads.cpp + Timer.cpp Version.cpp ADDITIONAL_HEADER_DIRS Index: lld/Common/Timer.cpp =================================================================== --- /dev/null +++ lld/Common/Timer.cpp @@ -0,0 +1,71 @@ +#include "lld/Common/Timer.h" +#include "lld/Common/ErrorHandler.h" +#include "llvm/Support/Format.h" + +using namespace lld; +using namespace llvm; + +ScopedTimer::ScopedTimer(Timer &T) : T(&T) { T.start(); } + +void ScopedTimer::stop() { + if (!T) + return; + T->stop(); + T = nullptr; +} + +ScopedTimer::~ScopedTimer() { stop(); } + +Timer::Timer(llvm::StringRef Name) : Name(Name), Parent(nullptr) {} +Timer::Timer(llvm::StringRef Name, Timer &Parent) + : Name(Name), Parent(&Parent) {} + +void Timer::start() { + if (Parent && Total.count() == 0) + Parent->Children.push_back(this); + StartTime = std::chrono::high_resolution_clock::now(); +} + +void Timer::stop() { + Total += (std::chrono::high_resolution_clock::now() - StartTime); +} + +Timer &Timer::root() { + static Timer RootTimer("Total Link Time"); + return RootTimer; +} + +void Timer::print() { + double TotalDuration = static_cast(root().millis()); + + // We want to print the grand total under all the intermediate phases, so we + // print all children first, then print the total under that. + for (const auto &Child : Children) + Child->print(1, TotalDuration); + + message(std::string(49, '-')); + + root().print(0, root().millis(), false); +} + +double Timer::millis() const { + return std::chrono::duration_cast>( + Total) + .count(); +} + +void Timer::print(int Depth, double TotalDuration, bool Recurse) const { + double P = 100.0 * millis() / TotalDuration; + + SmallString<32> Str; + llvm::raw_svector_ostream Stream(Str); + std::string S = std::string(Depth * 2, ' ') + Name + std::string(":"); + Stream << format("%-30s(%6.2f%%) %5d ms", S.c_str(), P, (int)millis()); + + message(Str); + + if (Recurse) { + for (const auto &Child : Children) + Child->print(Depth + 1, TotalDuration); + } +} Index: lld/include/lld/Common/Timer.h =================================================================== --- /dev/null +++ lld/include/lld/Common/Timer.h @@ -0,0 +1,59 @@ +//===- Timer.h ----------------------------------------------*- C++ -*-===// +// +// The LLVM Linker +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#ifndef LLD_COMMON_TIMER_H +#define LLD_COMMON_TIMER_H + +#include "llvm/ADT/DenseMap.h" +#include "llvm/ADT/StringRef.h" +#include +#include +#include +#include + +namespace lld { + +class Timer; + +struct ScopedTimer { + explicit ScopedTimer(Timer &T); + + ~ScopedTimer(); + + void stop(); + + Timer *T = nullptr; +}; + +class Timer { + std::chrono::time_point StartTime; + std::chrono::nanoseconds Total; + llvm::SmallVector Children; + std::string Name; + Timer *Parent; + void print(int Depth, double TotalDuration, bool Recurse = true) const; + explicit Timer(llvm::StringRef Name); + +public: + friend ScopedTimer; + + Timer(llvm::StringRef Name, Timer &Parent); + + static Timer &root(); + + void start(); + void stop(); + void print(); + + double millis() const; +}; + +} // namespace lld + +#endif