Index: lld/COFF/Config.h =================================================================== --- lld/COFF/Config.h +++ lld/COFF/Config.h @@ -10,6 +10,7 @@ #ifndef LLD_COFF_CONFIG_H #define LLD_COFF_CONFIG_H +#include "lld/Common/Timer.h" #include "llvm/ADT/StringRef.h" #include "llvm/Object/COFF.h" #include "llvm/Support/CachePruning.h" @@ -90,8 +91,10 @@ 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; // Symbols in this set are considered as live by the garbage collector. @@ -155,6 +158,9 @@ // Used for /lldmap. std::string MapFile; + // Used for /showtiming + Timer Metrics; + uint64_t ImageBase = -1; uint64_t StackReserve = 1024 * 1024; uint64_t StackCommit = 4096; Index: lld/COFF/Driver.cpp =================================================================== --- lld/COFF/Driver.cpp +++ lld/COFF/Driver.cpp @@ -13,6 +13,7 @@ #include "MinGW.h" #include "SymbolTable.h" #include "Symbols.h" +#include "Timing.h" #include "Writer.h" #include "lld/Common/Driver.h" #include "lld/Common/ErrorHandler.h" @@ -711,6 +712,9 @@ } bool LinkerDriver::run() { + Timer::TimerPhaseRAII Timer = + Config->Metrics.startPhaseRAII(TP_InputFileReading); + bool DidWork = !TaskQueue.empty(); while (!TaskQueue.empty()) { TaskQueue.front()(); @@ -762,6 +766,13 @@ return; } + if (Args.hasArg(OPT_show_timing)) { + Config->ShowTiming = true; + Config->Metrics.addPhase("Input File Reading", TP_InputFileReading); + } + Config->Metrics.enable(Config->ShowTiming); + Config->Metrics.startPhase(TP_Total); + // 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. @@ -1319,15 +1330,22 @@ createSideBySideManifest(); // Identify unreferenced COMDAT sections. - if (Config->DoGC) + if (Config->DoGC) { + Config->Metrics.addPhase("GC", TP_GC); markLive(Symtab->getChunks()); + } // Identify identical COMDAT sections to merge them. - if (Config->DoICF) + if (Config->DoICF) { + Config->Metrics.addPhase("ICF", TP_ICF); doICF(Symtab->getChunks()); + } // Write the result. writeResult(); + + Config->Metrics.stopPhase(TP_Total); + Config->Metrics.print(); } } // namespace coff Index: lld/COFF/ICF.cpp =================================================================== --- lld/COFF/ICF.cpp +++ lld/COFF/ICF.cpp @@ -20,6 +20,7 @@ #include "Chunks.h" #include "Symbols.h" +#include "Timing.h" #include "lld/Common/ErrorHandler.h" #include "llvm/ADT/Hashing.h" #include "llvm/Support/Debug.h" @@ -207,6 +208,8 @@ // Two sections are considered the same if their section headers, // contents and relocations are all the same. void ICF::run(ArrayRef Vec) { + Timer::TimerPhaseRAII Timer = Config->Metrics.startPhaseRAII(TP_ICF); + // 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,6 +9,7 @@ #include "Chunks.h" #include "Symbols.h" +#include "Timing.h" #include "llvm/ADT/STLExtras.h" #include @@ -19,6 +20,8 @@ // COMDAT chunks will be ignored by Writer, so they will be excluded // from the final output. void markLive(ArrayRef Chunks) { + Timer::TimerPhaseRAII Timer = Config->Metrics.startPhaseRAII(TP_GC); + // 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<"showtiming">; //============================================================================== // 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 @@ -13,8 +13,10 @@ #include "Driver.h" #include "SymbolTable.h" #include "Symbols.h" +#include "Timing.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" @@ -233,6 +235,9 @@ const CVIndexMap &PDBLinker::mergeDebugT(ObjFile *File, CVIndexMap &ObjectIndexMap) { + Timer::TimerPhaseRAII TypeMergingTimer = + Config->Metrics.startPhaseRAII(TP_PdbTypeMerging); + ArrayRef Data = getDebugSection(File, ".debug$T"); if (Data.empty()) return ObjectIndexMap; @@ -747,6 +752,9 @@ CVIndexMap ObjectIndexMap; const CVIndexMap &IndexMap = mergeDebugT(File, ObjectIndexMap); + Timer::TimerPhaseRAII SymbolTimer = + Config->Metrics.startPhaseRAII(TP_PdbSymbolMerging); + // Now do all live .debug$S sections. DebugStringTableSubsectionRef CVStrTab; DebugChecksumsSubsectionRef Checksums; @@ -864,12 +872,15 @@ // Add all object files to the PDB. Merge .debug$T sections into IpiData and // TpiData. void PDBLinker::addObjectsToPDB() { + Config->Metrics.startPhase(TP_PdbAddObjects); for (ObjFile *File : ObjFile::Instances) addObjFile(File); Builder.getStringTableBuilder().setStrings(PDBStrTab); + Config->Metrics.stopPhase(TP_PdbAddObjects); // Construct TPI and IPI stream contents. + Config->Metrics.startPhase(TP_PdbTpiConstruction); if (Config->DebugGHashes) { addTypeInfo(Builder.getTpiBuilder(), GlobalTypeTable); addTypeInfo(Builder.getIpiBuilder(), GlobalIDTable); @@ -877,6 +888,10 @@ addTypeInfo(Builder.getTpiBuilder(), TypeTable); addTypeInfo(Builder.getIpiBuilder(), IDTable); } + Config->Metrics.stopPhase(TP_PdbTpiConstruction); + + Timer::TimerPhaseRAII PublicsTimer = + Config->Metrics.startPhaseRAII(TP_PdbPublicsConstruction); // Compute the public and global symbols. auto &GsiBuilder = Builder.getGsiBuilder(); @@ -974,10 +989,29 @@ ArrayRef OutputSections, ArrayRef SectionTable, const llvm::codeview::DebugInfo &BuildId) { + Config->Metrics.addPhase("PDB Emission (Cumulative)", TP_PdbLinkTotal); + Config->Metrics.addPhase("Add Objects", TP_PdbAddObjects, TP_PdbLinkTotal); + + Config->Metrics.addPhase("Globals Stream Layout", TP_PdbPublicsConstruction, + TP_PdbLinkTotal); + Config->Metrics.addPhase("TPI Stream Layout", TP_PdbTpiConstruction, + TP_PdbLinkTotal); + Config->Metrics.addPhase("Type Merging", TP_PdbTypeMerging, TP_PdbAddObjects); + Config->Metrics.addPhase("Symbol Merging", TP_PdbSymbolMerging, + TP_PdbAddObjects); + Config->Metrics.addPhase("Commit to Disk", TP_PdbDiskCommit, TP_PdbLinkTotal); + + Timer::TimerPhaseRAII TotalTimer = + Config->Metrics.startPhaseRAII(TP_PdbLinkTotal); + PDBLinker PDB(Symtab); PDB.initialize(BuildId); PDB.addObjectsToPDB(); PDB.addSections(OutputSections, SectionTable); + + Timer::TimerPhaseRAII CommitTimer = + Config->Metrics.startPhaseRAII(TP_PdbDiskCommit); + PDB.commit(); } Index: lld/COFF/SymbolTable.cpp =================================================================== --- lld/COFF/SymbolTable.cpp +++ lld/COFF/SymbolTable.cpp @@ -12,6 +12,7 @@ #include "Driver.h" #include "LTO.h" #include "Symbols.h" +#include "Timing.h" #include "lld/Common/ErrorHandler.h" #include "lld/Common/Memory.h" #include "llvm/IR/LLVMContext.h" @@ -384,6 +385,10 @@ void SymbolTable::addCombinedLTOObjects() { if (BitcodeFile::Instances.empty()) return; + + Config->Metrics.addPhase("LTO", TP_LTO); + + Timer::TimerPhaseRAII Timer = Config->Metrics.startPhaseRAII(TP_LTO); for (StringRef Object : compileBitcodeFiles()) { auto *Obj = make(MemoryBufferRef(Object, "lto.tmp")); Obj->parse(); Index: lld/COFF/Timing.h =================================================================== --- /dev/null +++ lld/COFF/Timing.h @@ -0,0 +1,41 @@ +//===- Timing.h -------------------------------------------------*- C++ -*-===// +// +// The LLVM Linker +// +// This file is distributed under the University of Illinois Open Source +// License. See LICENSE.TXT for details. +// +//===----------------------------------------------------------------------===// + +#ifndef LLD_COFF_TIMING_H +#define LLD_COFF_TIMING_H + +#include "lld/Common/Timer.h" + +namespace lld { +namespace coff { +enum TimingPhases { + TP_Total, + + TP_InputFileReading, + TP_ImportLibrary, + TP_ICF, + TP_GC, + TP_LTO, + TP_CodeLayout, + TP_CodeDiskCommit, + + TP_PdbLinkTotal, + TP_PdbPublicsConstruction, + TP_PdbTpiConstruction, + TP_PdbAddObjects, + TP_PdbTypeMerging, + TP_PdbSymbolMerging, + TP_PdbDiskCommit, + + TP_Max, +}; +} +} // namespace lld + +#endif 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 @@ -15,6 +15,7 @@ #include "PDB.h" #include "SymbolTable.h" #include "Symbols.h" +#include "Timing.h" #include "lld/Common/ErrorHandler.h" #include "lld/Common/Memory.h" #include "llvm/ADT/DenseMap.h" @@ -284,6 +285,11 @@ // The main function of the writer. void Writer::run() { + Config->Metrics.addPhase("Code Layout", TP_CodeLayout); + Config->Metrics.addPhase("Commit Output File", TP_CodeDiskCommit); + + Config->Metrics.startPhase(TP_CodeLayout); + createSections(); createMiscChunks(); createImportTables(); @@ -308,16 +314,19 @@ sortExceptionTable(); writeBuildId(); - if (!Config->PDBPath.empty() && Config->Debug) { + Config->Metrics.stopPhase(TP_CodeLayout); + if (!Config->PDBPath.empty() && Config->Debug) { assert(BuildId); createPDB(Symtab, OutputSections, SectionTable, *BuildId->BuildId); } writeMapFile(OutputSections); + Config->Metrics.startPhase(TP_CodeDiskCommit); if (auto E = Buffer->commit()) fatal("failed to write the output file: " + toString(std::move(E))); + Config->Metrics.stopPhase(TP_CodeDiskCommit); } static StringRef getOutputSection(StringRef Name) { 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,125 @@ +#include "lld/Common/Timer.h" +#include "lld/Common/ErrorHandler.h" +#include "llvm/Support/FormatAdapters.h" +#include "llvm/Support/FormatVariadic.h" + +using namespace lld; +using namespace llvm; + +void Timer::TimerPhase::start() { + StartTime = std::chrono::high_resolution_clock::now(); +} + +void Timer::TimerPhase::stop() { + auto EndTime = std::chrono::high_resolution_clock::now(); + Total += std::chrono::duration_cast(EndTime - + StartTime); +} + +void Timer::TimerPhase::print(int Depth, int NameWidth, int Digits, + float TotalDuration, bool Recurse) const { + float P = 100.0f * (float)Total.count() / TotalDuration; + + int LI = Depth * 2; // left indent + int RI = NameWidth - Name.size() - 1 - LI; // right indent + + // Output line format is: + // name: + message(formatv("{0}({1,+6}%) {2:ms}", + fmt_pad(Name + ":", LI, RI), // name: + P, // (AAA.BB%) + fmt_align(Total, AlignStyle::Right, Digits + 3))); // ABCD ns + + if (Recurse) { + for (const auto &Child : ChildrenPhases) + Child.second->print(Depth + 1, NameWidth, Digits, TotalDuration); + } +} + +Timer::Timer() { + RootPhase.Name = "Total Link Time"; + AllPhases.insert(std::make_pair(0, &RootPhase)); +} + +Timer::~Timer() {} + +void Timer::addPhase(StringRef Name, int Code, TimerPhase &Parent) { + assert(Parent.ChildrenPhases.count(Code) == 0 && "Phase already exists!"); + auto NewPhase = make_unique(); + NewPhase->Name = Name; + + AllPhases.insert(std::make_pair(Code, NewPhase.get())); + Parent.ChildrenPhases.insert(std::make_pair(Code, std::move(NewPhase))); +} + +/// Add a link phase using the specified unique code. You can start and stop +/// time counting for this phase by calling startPhase(Code) or +/// stopPhase(Code). +void Timer::addPhase(StringRef Name, int Code) { + assert(AllPhases.count(Code) == 0 && "Phase already exists!"); + addPhase(Name, Code, RootPhase); +} + +/// Add a link phase using the specified code, indicating that this phase is +/// a child of another phase. Child phases will be printed under their +/// parent phases, and indented to visually indicate that it is a child. +void Timer::addPhase(StringRef Name, int Code, int Parent) { + assert(AllPhases.count(Parent) == 1 && "Parent phase doesn't exist!"); + + TimerPhase *ParentPtr = AllPhases[Parent]; + addPhase(Name, Code, *ParentPtr); +} + +void Timer::startPhase(int Code) { + if (!EnableTiming) + return; + + assert(AllPhases.count(Code) == 1 && "Can't start phase that doesn't exist!"); + AllPhases[Code]->start(); +} + +void Timer::stopPhase(int Code) { + if (!EnableTiming) + return; + + assert(AllPhases.count(Code) == 1 && "Can't stop phase that doesn't exist!"); + AllPhases[Code]->stop(); +} + +Timer::TimerPhaseRAII Timer::startPhaseRAII(int Code) { + if (!EnableTiming) + return {}; + + assert(AllPhases.count(Code) == 1 && "Can't start phase that doesn't exist!"); + return TimerPhaseRAII(*AllPhases[Code]); +} + +int Timer::calculateNameFieldWidth(int Depth, const TimerPhase &Phase) const { + // indentation, then name, then a colon and a space. + int MaxLen = 2 * Depth + Phase.Name.size() + 2; + for (const auto &Child : Phase.ChildrenPhases) + MaxLen = + std::max(MaxLen, calculateNameFieldWidth(Depth + 1, *Child.second)); + return MaxLen; +} + +void Timer::print() const { + if (!EnableTiming) + return; + + float TotalDuration = static_cast(RootPhase.Total.count()); + int Digits = std::ceil(std::log10f(TotalDuration)); + + // We want to print the grand total under all the intermediate phases, so we + // special case this by printing all children first, rather than just + // immediately calling RootPhase.print() + int NameWidth = calculateNameFieldWidth(0, RootPhase); + for (const auto &Child : RootPhase.ChildrenPhases) { + Child.second->print(1, NameWidth, Digits, TotalDuration); + } + + int RowLength = NameWidth + 11 + Digits + 3; // ( AB.CD%) ms + message(formatv("{0}", fmt_repeat("-", RowLength))); + + RootPhase.print(0, NameWidth, Digits, RootPhase.Total.count(), false); +} Index: lld/include/lld/Common/Timer.h =================================================================== --- /dev/null +++ lld/include/lld/Common/Timer.h @@ -0,0 +1,94 @@ +//===- 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 { + +/// Provides a way to time various phases of the linker. The set of phases to +/// be timed is dynamic, so that for example you can add phases as necessary +/// based on the command line options given. Phases can have sub-phases, so +/// that a large operation (for example linking of a PDB file) can show total +/// time but still be broken down into the individual steps of PDB linking. +/// Note that the timer does *not* automatically accumulate the duration of +/// child phases to compute the duration of a parent phase. All accounting is +/// manual. The separation of child / parent phases is purely for aesthetic +/// reasons in the formatted output. +/// All phases must be added at runtime using a unique code, with the exception +/// of the root phase, which always has Code 0. +class Timer { + struct TimerPhase { + void start(); + void stop(); + void print(int Depth, int NameWidth, int Digits, float TotalDuration, + bool Recurse = true) const; + + std::chrono::time_point StartTime; + std::chrono::milliseconds Total; + std::map> ChildrenPhases; + std::string Name; + }; + + bool EnableTiming = false; + llvm::DenseMap AllPhases; + TimerPhase RootPhase; + + int calculateNameFieldWidth(int Depth, const TimerPhase &Parent) const; + void addPhase(llvm::StringRef Name, int Code, TimerPhase &Parent); + +public: + struct TimerPhaseRAII { + TimerPhaseRAII() = default; + + explicit TimerPhaseRAII(TimerPhase &T) : T(&T) { T.start(); } + + ~TimerPhaseRAII() { + if (T) + T->stop(); + } + + TimerPhase *T = nullptr; + }; + + Timer(); + ~Timer(); + + void enable(bool Enable) { EnableTiming = Enable; } + + /// Add a link phase using the specified unique code. You can start and stop + /// time counting for this phase by calling startPhase(Code) or + /// stopPhase(Code). + void addPhase(llvm::StringRef Name, int Code); + + /// Add a link phase using the specified code, indicating that this phase is + /// a child of another phase. Child phases will be printed under their + /// parent phases, and indented to visually indicate that it is a child. + void addPhase(llvm::StringRef Name, int Code, int Parent); + + void startPhase(int Code); + void stopPhase(int Code); + TimerPhaseRAII startPhaseRAII(int Code); + + /// Print all timing information. Phases will be printed in numerical order + /// by their code, with child phases always appearing directly under (and + /// indented from) parent phases. + void print() const; +}; + +} // namespace lld + +#endif