[lldCOFF] Print detailed timing information with /VERBOSE

[zturner]

Summary

When passing /VERBOSE, lld will now print detailed timing information about the various linking phases. For example, when linking clang with /verbose, I get this output:

Timing:
  Code Layout Time:          (  1.38%)   229 ms
  Commit Output File:        (  0.09%)    15 ms
  PDB Emission (Cumulative): ( 96.03%) 15969 ms
    Globals Stream Layout:   (  1.18%)   197 ms
    Symbol Merging:          ( 26.26%)  4367 ms
    Type Merging:            ( 36.94%)  6142 ms
    TPI Stream Layout:       (  6.95%)  1155 ms
    Commit to Disk:          ( 18.65%)  3101 ms
-----------------------------------------------
  Total Link Time:           (100.00%) 16629 ms

[ruiu]

lld/COFF/Config.h

112 ↗

(On Diff #129327)

Why do you have to store them to Config? Config is for configuration variables and not a generic place to store miscellaneous data.

lld/COFF/PDB.cpp

1014–1015 ↗

(On Diff #129327)

These things should be done in the RAII style.

lld/COFF/Writer.cpp

289 ↗

(On Diff #129327)

I'd print out the timing information as we measure, instead of printing out all the information at end.

309–328 ↗

(On Diff #129327)

Please avoid using formatv in lld because we do not use it in other places in lld. We don't remember the format string format.

[zturner]

lld/COFF/PDB.cpp

1014–1015 ↗

(On Diff #129327)

I didn't do RAII style here because we want to start and stop in the middle of functions sometimes. It seemed inconvenient to have to make a nested scope just for that.

lld/COFF/Writer.cpp

289 ↗

(On Diff #129327)

If we do it this way it might not all appear together. This will make it harder to parse the output, as you might have to scroll the terminal around to find the different pieces of information you're interested in.

309–328 ↗

(On Diff #129327)

It's pretty ugly to do any kind of nice alignment without it. I try to avoid it if there's a better way, but in this case I think it would add a lot of additional code for no real benefit.

[ruiu]

lld/COFF/PDB.cpp

1014–1015 ↗

(On Diff #129327)

I guess it's because the timing information is printed out along with other debug info. How about adding a new command line just for this feature?

[ruiu]

lld/COFF/PDB.cpp

1014–1015 ↗

(On Diff #129327)

It's worth noting that /verbose makes the linker slower because generating and emitting debug messages is sometimes not cheap. For that reason it makes sense to separate the flag.

[zturner]

• Moved the printing and collection of this information out of /VERBOSE and into a new option, /SHOWTIMING.

• Removed a few explicit calls to Timer.end() where RAII-style end would work (the class already calls end() in its destructor anyway). A few calls to end() are still explicit, where we need to do it in the middle of a function.

• Moved the statistics out of the Config class and into a separate class called TimingInfo, which is created in Writer and passed through to the PDB linker.

[pcc]

Could this also include some of the earlier linking phases in Driver.cpp (I'm thinking input file reading, GC, ICF)?

[zturner]

In D41915#972686, @pcc wrote:

Could this also include some of the earlier linking phases in Driver.cpp (I'm thinking input file reading, GC, ICF)?

Yea, I can do that. Stay tuned.

[ruiu]

lld/COFF/Driver.cpp

834–836 ↗

(On Diff #129342)

For consistency:

// Handle /showtiming
if (Args.hasArg(OPT_show_timing))
  Config->ShowTiming = true;

lld/include/lld/Common/LinkTimer.h

18 ↗

(On Diff #129342)

Since everything in lld namespace is related to linking, I'd name this Timer.

21 ↗

(On Diff #129342)

Why don't you use nanosecond?

30 ↗

(On Diff #129342)

Please write the actual type instead of auto.

31 ↗

(On Diff #129342)

It is better to use chrono::high_resolution_clock, or at least chrono::steady_clock. system_clock is not guaranteed to be monotonic (so it can rewind.)

[zturner]

I went to start implementing peter's suggestion, and things started getting a little interesting. A lot of the things you might want to time are behind command line options, and it would be nice if we didn't show anything when the lines weren't relevant.

At the same time, I don't like writing code and then having someone re-invent the same thing later that is slightly different. So although nobody's using this now, I wanted to do this in a way that could benefit, for example, the ELF linker or the MachO linker at some point in the future.

So I tried to generalize this a little bit. Everything is moved into Common now, and the only thing defined in COFF is a set of enums that represent the various statistics that you might want to time. You can add phases dynamically (for example, only if an option is set on the command line), and all the printing logic is raised up into common too, and it does all the work of figuring out the right set of statistics you're timing, calculating percentages, etc, so nobody else has to deal with the formatting and alignment again.

just to illustrate what I mean, currently when I link with /OPT:REF + /OPT:ICF + /DEBUG I get this:

  Input File Reading:        (  3.54%)   576 ms
  ICF:                       (  0.66%)   107 ms
  GC:                        (  1.34%)   218 ms
  Code Layout:               (  0.79%)   128 ms
  Commit Output File:        (  0.07%)    11 ms
  PDB Emission (Cumulative): ( 93.46%) 15214 ms
    Globals Stream Layout:   (  1.09%)   177 ms
    TPI Stream Layout:       (  6.71%)  1093 ms
    Type Merging:            ( 35.43%)  5767 ms
    Symbol Merging:          ( 24.43%)  3977 ms
    Commit to Disk:          ( 17.90%)  2913 ms
------------------------------------------------
Total Link Time:             (100.00%) 16278 ms

whereas if I link with only /OPT:ICF and /OPT:REF but remove /DEBUG I get this:

  Input File Reading: ( 54.80%) 542 ms
  ICF:                ( 11.93%) 118 ms
  GC:                 ( 16.38%) 162 ms
  Code Layout:        ( 13.14%) 130 ms
  Commit Output File: (  1.31%)  13 ms
---------------------------------------
Total Link Time:      (100.00%) 989 ms

I think this is a more friendly output and more useful from a usability perspective. But if I went a little overboard let me know :)

[pcc]

lld/COFF/Driver.cpp

951 ↗

(On Diff #129375)

I gather that the intent is to add a "ThinLTO" phase to the timing output only if we end up doing LTO, but a user is not required to pass this flag in order to use LTO. Instead, we always perform LTO if the user passes at least one bitcode input file. You can find the check for that condition as well as the code that actually does LTO in the function SymbolTable::addCombinedLTOObject().

Also, I'd call this "LTO" and not "ThinLTO" because the linker supports both full and thin LTO.

[zturner]

• Renamed LinkTimer to Timer, as suggested by Rui.
• Moved the LTO setup into the proper place.
• Changed from system_clock to high_resolution_clock.

I didn't change ms to nanoseconds because I find nanoseconds hard to read. It prints more than 10 digits of numbers, and it takes some mental strain to translate that back into something I can understand. If anyone feels strongly that ms is not a fine enough granularity though, let me know. Making the milliseconds a floating point might be another alternative.

[zturner]

Storing the accumulated time in nanoseconds. Turns out when you store in milliseconds you can accumulate a large amount of truncation error. So I'm now accumulating nanoseconds but still printing milliseconds.

[ruiu]

lld/COFF/Driver.cpp

715 ↗

(On Diff #129495)

Timer::TimerPhaseRAII is too long. I'd name this ScopedTimer and name the local variable T. As long as you use T as a name for the timer, there should be no confusion. I imagine that you could use it like this:

ScopedTimer T(TotalTimer);

lld/COFF/Timing.h

17 ↗

(On Diff #129495)

Instead of defining one timer which contains multiple timers in it, can you define a timer for each measurement like this?

namespace lld {
namespace coff {
Timer TotalTimer("Total");
Timer FileReadTimer("Input File Reading");
...
}
}

Then you can remove this enum.

lld/Common/Timer.cpp

14 ↗

(On Diff #129495)

Please do not use auto.

18 ↗

(On Diff #129495)

Use double unless there's a reason to use float.

34 ↗

(On Diff #129495)

Instead of formatv, please use llvm::format which takes printf-style format string. It is more familiar (and thus easy to read) to most people who work on lld.

103 ↗

(On Diff #129495)

This is a bit too overdesigned at the moment. Just use some fixed width (e.g. 20 chars) as the width of the name field. I'd reduce the amount of code as much as possible.

lld/include/lld/Common/Timer.h

56 ↗

(On Diff #129495)

I don't think there's a valid use case for this constructor.

[zturner]

lld/COFF/Timing.h

17 ↗

(On Diff #129495)

The whole idea is that a single class aggregates all of the timers so that at the end, there is one print function that handles all the formatting and alignment. Also, how would nested timers work? For example, I want to have a timer for "PDB Link Time" but then subtimers for the various phases of PDB linking, and those should be indented under the main timer to make it easier to understand the results. See some of the sample outputs I posted earlier, for example.

You could make it all work by having Timer contain a TimerManager&, and then writing something like:

namespace lld {
namespace coff {
TimerManager Timers;
Timer TotalTimer("Total", Timers);
Timer FileReadTimer("Input File Reading", Timers);
...
}
}

but this looks like a worse API to me. Finally, there is the issue of dynamic timers. If someone doesn't pass /DEBUG on the command line, there is no reason to have a bunch of output related to PDB linking phases. So this is why there is the addPhase function, which will add a timer dynamically.

I think this gives the best output.

lld/Common/Timer.cpp

34 ↗

(On Diff #129495)

Can you show me a printf line that prints N spaces, followed by a string, followed by M spaces, followed by a some right aligned text? I honestly don't know how to do this with printf.

That said, I don't know why we should be scared of or avoid using standard LLVM support types and classes. It's about the same as a python format string, and once you do understand it, it's much easier (not to mention safer) than printf format string. printf format strings are also the source of countless portability bugs.

The code here doesn't really use anything fancy, and it's mostly self explanatory since instead of embedding all the formatting in the format string, I used the adapters like fmt_align which spell out exactly what they're doing, so familiarity shouldn't be an issue.

103 ↗

(On Diff #129495)

I have a separate patch offline which adds some more timers and which goes past 20. So this would cause it to not be aligned. We can make it 40, or 60, but then it will look ugly in most cases. This is all code hidden behind an option that you have to explicitly specify, so is there any disadvantage to just doing it "correctly"?

[ruiu]

lld/COFF/Timing.h

17 ↗

(On Diff #129495)

We can organize timer "trees" by passing "parent" timer to child timers like this:

Timer TotalTimer("Total");
Timer FileReadTimer("Input File Reading", &TotalTimer);

And then make timer's "print" function print out its timing information as well as its children's timing information. Then all you have to do at end is to call the "print" function on TotalTimer which recursively prints out all timer info.

lld/Common/Timer.cpp

34 ↗

(On Diff #129495)

You may be more familiar with this format string than printf-style format string, but that's not true for many other people. And honestly I don't think people would want to spend time on understanding the new format string that occur only a few times in lld (even for making sure that that's the same as Python's format string.) lld is part of the LLVM project, but at the same time, this is a project that people who are not working on LLVM/Clang are interested in, and I don't want to use an LLVM-specific utility if the more language-standard-ish one works sufficiently.

As to how to write it in printf, how about this?

$ printf '% 20s: (% .2f%%) % 5d ms\n' 'Code layout time' 1.379 229
Code layout time: ( 1.38%)   229 ms

103 ↗

(On Diff #129495)

The disadvantage is the amount of code and time to understand how it works. Please keep it simple even if it looks a bit stupid. In addition to that, calculating the width doesn't create a desired output. If some timer is 80 columns long, you'll get something like

Timing:
  Code Layout Time:                                                                            (  1.38%)   229 ms
  Commit Output File:                                                                          (  0.09%)    15 ms
  Very loooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooong name: (  0.00%)     0 ms
  PDB Emission (Cumulative):                                                                   ( 96.03%) 15969 ms
    Globals Stream Layout:                                                                     (  1.18%)   197 ms
    Symbol Merging:                                                                            ( 26.26%)  4367 ms
    Type Merging:                                                                              ( 36.94%)  6142 ms
    TPI Stream Layout:                                                                         (  6.95%)  1155 ms
    Commit to Disk:                                                   ( 18.65%)  3101 ms
-----------------------------------------------
  Total Link Time:           (100.00%) 16629 ms

I think what we want to do is to insert a reasonable number of space between ':' and '(' so it doesn't wrap around for most lines. We should format this assuming that the terminal size is 80 columns, so variable width is not really desirable.

Timing:
  Code Layout Time:             (  1.38%)   229 ms
  Commit Output File:           (  0.09%)    15 ms
Very loooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooong name: (  0.00%)     0 ms
  PDB Emission (Cumulative):    ( 96.03%) 15969 ms
    Globals Stream Layout:      (  1.18%)   197 ms
    Symbol Merging:             ( 26.26%)  4367 ms
    Type Merging:               ( 36.94%)  6142 ms
    TPI Stream Layout:          (  6.95%)  1155 ms
    Commit to Disk:             ( 18.65%)  3101 ms
-----------------------------------------------
  Total Link Time:           (100.00%) 16629 ms

[zturner]

Fixes suggested by rui.

[ruiu]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

Can you remove addChildTimer if you pass a parent timer to the constructor?

lld/COFF/PDB.cpp

897 ↗

(On Diff #129557)

I found T1, T2, ... (which you did in Writer.cpp) is better than T, U, V.

lld/Common/Timer.cpp

8 ↗

(On Diff #129557)

High resolution timer is very cheap on modern processors (I believe it is compiled to RSTSC instruction on x86, for example), so I think we should always enable this and just don't print out the final result if Config->ShowTiming is false.

62 ↗

(On Diff #129557)

I believe this can be written without repeat:

Stream << std::string('-', 49);

80–87 ↗

(On Diff #129557)

std::string S = (std::string(' ', Depth * 2) + Name).str();
format("% 30s (%6.2f%%) %5d ms", S, 100 * millis() / TotalDuration, (int)millis());

is perhaps a bit easier to read?

lld/include/lld/Common/Timer.h

35–41 ↗

(On Diff #129557)

We usually write private members after public members.

[zturner]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

No because we don't want every timer to be enabled always. Only if a certain branch of code is run (for example we only want to add PDB timers if /DEBUG is specified)

[rnk]

I'd suggest putting this under MSVC's /TIME flag: https://cs.chromium.org/chromium/src/build/config/win/BUILD.gn?type=cs&q=win_linker_timing&sq=package:chromium&l=281

It would then naturally work in Chrome builds that set the win_linker_timing=true gn args.

[zturner]

More fixes as suggested by rui

[zturner]

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

This isn't quite the same. printf right justifies %30s, I want it left justified. I also don't want it left justified to 30, because the indentation would have changed that. I think it's easier to just explicitly pad on the left and pad on the right.

[ruiu]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

But I don't think we need a separate flag. It seems you can show timing information only when a timer has non-zero time duration (which means the timer has activated and deactivated).

lld/COFF/PDB.cpp

998 ↗

(On Diff #129699)

T1 and T2?

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

std::string S = (std::string(' ', Depth * 2) + Name).str();

indents the string, no?

[zturner]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

That's an option, but would there be issues if we use a "Parent" that is defined in another translation unit. The child will call parent->Children.add(*this). Can we guarantee that the Parent has been constructed at that point? I always forget when it's safe for one global variable to use another. If we have to introduce ManagedStatic or something then I think it just makes the code more complicated.

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

Yes, but then the %30s is no longer correct, because some of the 30 has been consumed by the Depth*2 characters on the left. The point is that after indenting, the field width is no longer a constant. That said, I think this code is pretty simple already no?

[ruiu]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

Good point, but you could add a timer to its parent not when the constructor is executed but when it's start()'ed.

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

Aah, sorry I misunderstood the issue. Can't you use '% -30s'? It left-justifies the string.

[zturner]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

We might start and stop it many times though (we already do this in PDB.cpp with TypeMergingTimer, for example). So if we do it that way we'd need to make sure it hasn't already been added, at which point we have to use a map of some kind instead of a simple vector.

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

If we append the spaces first to construct a temporary string then that should work, but that results in some extra copies. I don't think it would result in shorter or fewer lines of code either.

[ruiu]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

I don't think we need a map. A timer can add itself to a parent timer first time start() is called -- which is when the timer duration is zero.

lld/Common/Timer.cpp

80–87 ↗

(On Diff #129557)

Creating extra copies is fine -- it's very small amount of data, and

std::string S = (std::string(' ', Depth * 2) + Name + ":").str();
Stream << format("% -30s (%6.2f%%) %5d ms", S, 100 * millis() / TotalDuration, (int)millis());

is apparently shorter than 8 lines of code.

[zturner]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

Currently a timer does not store a pointer to its parent. In order to do this it would have to store that. Should I make that change?

[ruiu]

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

Good point, and I'm almost convinced, but I'd think we still want it. The current API is easy to misuse. I think you forgot to call addChildTimer for LTOTimer.

[zturner]

Fix remaining issues.

[ruiu]

Overall looking pretty good.

lld/COFF/Driver.cpp

50 ↗

(On Diff #129557)

Ah, this is a very nice way to force some initialization order. Thank you for doing this.

lld/include/lld/Common/Timer.h

35–41 ↗

(On Diff #129721)

Please move private members after public members.

37 ↗

(On Diff #129721)

I'd use std::vector when we do not have to optimize for speed.

41 ↗

(On Diff #129721)

This constructor is used only by root(), so I'd make this private to prevent misuse of this constructor.

44 ↗

(On Diff #129721)

It looks like ScopedTimer accesses only public functions of this class.

[ruiu]

I tried to run this patch and found that printing out the timer tree as a tree like this

Total Link Time:              (100.00%)  6470 ms
  Input File Reading:         (  0.00%)     0 ms
  ICF:                        (  0.00%)     0 ms
  GC:                         (  0.00%)     0 ms
  LTO:                        (  0.00%)     0 ms
  Code Layout:                (  0.00%)     0 ms
  Commit Output File:         (  0.00%)     0 ms
  PDB Emission (Cumulative):  (  0.00%)     0 ms
    Add Objects:              (  0.00%)     0 ms
      Type Merging:           (  0.00%)     0 ms
      Symbol Merging:         (  0.00%)     0 ms
  ...

is more natural than the current format

  Input File Reading:         (  0.00%)     0 ms
  ICF:                        (  0.00%)     0 ms
  GC:                         (  0.00%)     0 ms
  LTO:                        (  0.00%)     0 ms
  Code Layout:                (  0.00%)     0 ms
  Commit Output File:         (  0.00%)     0 ms
  PDB Emission (Cumulative):  (  0.00%)     0 ms
    Add Objects:              (  0.00%)     0 ms
      Type Merging:           (  0.00%)     0 ms
      Symbol Merging:         (  0.00%)     0 ms
  ...
-------------------------------------------------
Total Link Time:              (100.00%)  6470 ms

which handles only the root timer in a special way because the former represents a tree as-is. Do you mind if I ask you to change the format?

[ruiu]

I didn't notice until I actually tried to use this, but showing only the total in the reverse order actually confused me about how to interpret the "Total" after the separator "-------------". Turned out that the the last line after the hyphen line is a continuation of the previous lines, but that wasn't very intuitive to me.

Also, this order looks a bit odd to me

PDB Emission (Cumulative): ( 96.03%) 15969 ms

because parenthesized number describes not the following but the preceding number. I feel

PDB Emission (Cumulative): 15969 ms ( 96.03%)

is more natural.

The other point I noticed is that we probably need only one digit after the decimal point for the percentage number. We truncate duration to milliseconds, and compared to that, showing two digits after the decimal point is disproportionally precise for the percentage.

[zturner]

Reversed the order of the time and the percentage, and formatted the percentage with only 1 decimal.

[ruiu]

LGTM with these changes.

Please update the commit message as it no longer depends on /VERBOSE.

lld/include/lld/Common/Timer.h

35 ↗

(On Diff #129996)

Move private members after public members.

37 ↗

(On Diff #129996)

Please use std::vector.

41 ↗

(On Diff #129996)

Make this private.

44 ↗

(On Diff #129996)

Please remove friend. I believe this file compiles without it.

[ruiu]

It seems it is still showing the total timer at the end. Can you fix it?

[takuto.ikuta]

Common/Timer.cpp

1

Do you forget adding LICENSE statement in this file?

COFF/Config.h

struct Configuration {
   std::string ImportName;
   bool DoGC = true;
   bool DoICF = true;
   bool Relocatable = true;
   bool Force = false;
   bool Debug = false;
   bool DebugDwarf = false;
   bool DebugGHashes = false;
+  bool ShowTiming = false;
   unsigned DebugTypes = static_cast<unsigned>(DebugType::None);
   llvm::SmallString<128> PDBPath;
   std::vector<llvm::StringRef> Argv;
 
   // Symbols in this set are considered as live by the garbage collector.
   std::vector<Symbol *> GCRoot;
 
   std::set<StringRef> NoDefaultLibs;

COFF/Driver.cpp

 #include "InputFiles.h"
 #include "MinGW.h"
 #include "SymbolTable.h"
 #include "Symbols.h"
 #include "Writer.h"
 #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"
 #include "llvm/BinaryFormat/Magic.h"
 #include "llvm/Object/ArchiveWriter.h"
 #include "llvm/Object/COFFImportFile.h"
 #include "llvm/Object/COFFModuleDefinition.h"
 #include "llvm/Option/Arg.h"

 using namespace llvm;
 using namespace llvm::object;
 using namespace llvm::COFF;
 using llvm::sys::Process;
 
 namespace lld {
 namespace coff {
 
+static Timer InputFileTimer("Input File Reading", Timer::root());
+
 Configuration *Config;
 LinkerDriver *Driver;
 
 bool link(ArrayRef<const char *> Args, bool CanExitEarly, raw_ostream &Diag) {
   errorHandler().LogName = Args[0];
   errorHandler().ErrorOS = &Diag;
   errorHandler().ColorDiagnostics = Diag.has_colors();
   errorHandler().ErrorLimitExceededMsg =
for (StringRef Path : Temps)
     sys::fs::remove(Path);
 }
 
 void LinkerDriver::enqueueTask(std::function<void()> Task) {
   TaskQueue.push_back(std::move(Task));
 }
 
 bool LinkerDriver::run() {
+  ScopedTimer T(InputFileTimer);
+
   bool DidWork = !TaskQueue.empty();
   while (!TaskQueue.empty()) {
     TaskQueue.front()();
     TaskQueue.pop_front();
   }
   return DidWork;
 }
 
void LinkerDriver::link(ArrayRef<const char *> ArgsArr) {
   }
 
   // Handle /help
   if (Args.hasArg(OPT_help)) {
     printHelp(ArgsArr[0]);
     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.
   if (Args.hasArg(OPT_dash_dash_version)) {
     outs() << getLLDVersion() << "\n";
     return;
   }
 
if (!Config->Exports.empty() || Config->DLL) {
     fixupExports();
     createImportLibrary(/*AsLib=*/false);
     assignExportOrdinals();
   }
 
   // Handle /output-def (MinGW specific).
   if (auto *Arg = Args.getLastArg(OPT_output_def))
     writeDefFile(Arg->getValue());
   
   // Set extra alignment for .comm symbols
   for (auto Pair : Config->AlignComm) {
     StringRef Name = Pair.first;
     uint32_t Alignment = Pair.second;
 
     Symbol *Sym = Symtab->find(Name);
     if (!Sym) {
       warn("/aligncomm symbol " + Name + " not found");
if (Config->DoGC)
     markLive(Symtab->getChunks());
 
   // Identify identical COMDAT sections to merge them.
   if (Config->DoICF)
     doICF(Symtab->getChunks());
 
   // Write the result.
   writeResult();
+
+  // Stop early so we can print the results.
+  Timer::root().stop();
+  if (Config->ShowTiming)
+    Timer::root().print();
 }
 
 } // namespace coff
 } // namespace lld

COFF/ICF.cpp

 //
 // See ELF/ICF.cpp for the details about the algortihm.
 //
 //===----------------------------------------------------------------------===//
 
 #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"
 #include "llvm/Support/raw_ostream.h"
 #include <algorithm>
 #include <atomic>
 #include <vector>
 
 using namespace llvm;
 
 namespace lld {
 namespace coff {
 
+static Timer ICFTimer("ICF", Timer::root());
+
 class ICF {
 public:
   void run(ArrayRef<Chunk *> V);
 
 private:
   void segregate(size_t Begin, size_t End, bool Constant);
 
   bool equalsConstant(const SectionChunk *A, const SectionChunk *B);
void ICF::forEachClass(std::function<void(size_t, size_t)> Fn) {
   });
   ++Cnt;
 }
 
 // Merge identical COMDAT sections.
 // Two sections are considered the same if their section headers,
 // contents and relocations are all the same.
 void ICF::run(ArrayRef<Chunk *> Vec) {
+  ScopedTimer T(ICFTimer);
+
   // Collect only mergeable sections and group by hash value.
   uint32_t NextId = 1;
   for (Chunk *C : Vec) {
     if (auto *SC = dyn_cast<SectionChunk>(C)) {
       if (isEligible(SC))
         Chunks.push_back(SC);
       else
         SC->Class[0] = NextId++;

COFF/MarkLive.cpp

 //===- MarkLive.cpp -------------------------------------------------------===//
 //
 //                             The LLVM Linker
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "Chunks.h"
 #include "Symbols.h"
+#include "lld/Common/Timer.h"
 #include "llvm/ADT/STLExtras.h"
 #include <vector>
 
 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<Chunk *> 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.
   SmallVector<SectionChunk *, 256> Worklist;
 
   // COMDAT section chunks are dead by default. Add non-COMDAT chunks.
   for (Chunk *C : Chunks)
     if (auto *SC = dyn_cast<SectionChunk>(C))

COFF/Options.td

 def rsp_quoting : Joined<["--"], "rsp-quoting=">,
   HelpText<"Quoting style for response files, 'windows' (default) or 'posix'">;
 def dash_dash_version : Flag<["--"], "version">,
   HelpText<"Print version information">;
 
 // 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.
 //==============================================================================
 
 class QF<string name> : Joined<["/", "-", "-?"], name#":">;
 
 multiclass QB<string name> {

COFF/PDB.cpp

 #include "PDB.h"
 #include "Chunks.h"
 #include "Config.h"
 #include "Driver.h"
 #include "SymbolTable.h"
 #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"
 #include "llvm/DebugInfo/CodeView/LazyRandomTypeCollection.h"
 #include "llvm/DebugInfo/CodeView/MergingTypeTableBuilder.h"
 #include "llvm/DebugInfo/CodeView/RecordName.h"
 #include "llvm/DebugInfo/CodeView/SymbolDeserializer.h"
 #include "llvm/DebugInfo/CodeView/SymbolSerializer.h"

 using namespace lld::coff;
 using namespace llvm;
 using namespace llvm::codeview;
 
 using llvm::object::coff_section;
 
 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.
 struct CVIndexMap {
   SmallVector<TypeIndex, 0> TPIMap;
   SmallVector<TypeIndex, 0> IPIMap;
   bool IsTypeServerMap = false;
 };
maybeReadTypeServerRecord(CVTypeArray &Types) {
   TypeServer2Record TS;
   if (auto EC = TypeDeserializer::deserializeAs(const_cast<CVType &>(Type), TS))
     fatal("error reading type server record: " + toString(std::move(EC)));
   return std::move(TS);
 }
 
 const CVIndexMap &PDBLinker::mergeDebugT(ObjFile *File,
                                          CVIndexMap &ObjectIndexMap) {
+  ScopedTimer T(TypeMergingTimer);
+
   ArrayRef<uint8_t> Data = getDebugSection(File, ".debug$T");
   if (Data.empty())
     return ObjectIndexMap;
 
   BinaryByteStream Stream(Data, support::little);
   CVTypeArray Types;
   BinaryStreamReader Reader(Stream);
   if (auto EC = Reader.readArray(Types, Reader.getLength()))
void PDBLinker::addObjFile(ObjFile *File) {
 
   // Before we can process symbol substreams from .debug$S, we need to process
   // type information, file checksums, and the string table.  Add type info to
   // the PDB first, so that we can get the map from object file type and item
   // indices to PDB type and item indices.
   CVIndexMap ObjectIndexMap;
   const CVIndexMap &IndexMap = mergeDebugT(File, ObjectIndexMap);
 
+  ScopedTimer T(SymbolMergingTimer);
+
   // Now do all live .debug$S sections.
   DebugStringTableSubsectionRef CVStrTab;
   DebugChecksumsSubsectionRef Checksums;
   std::vector<ulittle32_t *> StringTableReferences;
   for (SectionChunk *DebugChunk : File->getDebugChunks()) {
     if (!DebugChunk->isLive() || DebugChunk->getSectionName() != ".debug$S")
       continue;
 
static PublicSym32 createPublic(Defined *Def) {
   Pub.Offset = Def->getRVA() - OS->getRVA();
   Pub.Segment = OS->SectionIndex;
   return Pub;
 }
 
 // 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);
   } else {
     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<PublicSym32> Publics;
   Symtab->forEachSymbol([&Publics](Symbol *S) {
     // Only emit defined, live symbols that have a chunk.
     auto *Def = dyn_cast<Defined>(S);
     if (Def && Def->isLive() && Def->getChunk())
       Publics.push_back(createPublic(Def));
Mod.addSymbol(codeview::SymbolSerializer::writeOneSymbol(
       Sym, Allocator, CodeViewContainer::Pdb));
 }
 
 // Creates a PDB file.
 void coff::createPDB(SymbolTable *Symtab,
                      ArrayRef<OutputSection *> OutputSections,
                      ArrayRef<uint8_t> 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();
 }
 
 void PDBLinker::initialize(const llvm::codeview::DebugInfo &BuildId) {
   ExitOnErr(Builder.initialize(4096)); // 4096 is blocksize
 
   // Create streams in MSF for predefined streams, namely
   // PDB, TPI, DBI and IPI.

COFF/SymbolTable.cpp

 //===- SymbolTable.cpp ----------------------------------------------------===//
 //
 //                             The LLVM Linker
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 
 #include "SymbolTable.h"
 #include "Config.h"
 #include "Driver.h"
 #include "LTO.h"
 #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"
 #include <utility>
 
 using namespace llvm;
 
 namespace lld {
 namespace coff {
 
+static Timer LTOTimer("LTO", Timer::root());
+
 SymbolTable *Symtab;
 
 void SymbolTable::addFile(InputFile *File) {
   log("Reading " + toString(File));
   File->parse();
 
   MachineTypes MT = File->getMachineType();
   if (Config->Machine == IMAGE_FILE_MACHINE_UNKNOWN) {
std::vector<StringRef> SymbolTable::compileBitcodeFiles() {
   for (BitcodeFile *F : BitcodeFile::Instances)
     LTO->add(*F);
   return LTO->compile();
 }
 
 void SymbolTable::addCombinedLTOObjects() {
   if (BitcodeFile::Instances.empty())
     return;
+
+  ScopedTimer T(LTOTimer);
   for (StringRef Object : compileBitcodeFiles()) {
     auto *Obj = make<ObjFile>(MemoryBufferRef(Object, "lto.tmp"));
     Obj->parse();
     ObjFile::Instances.push_back(Obj);
   }
 }
 
 } // namespace coff
 } // namespace lld

COFF/Writer.h

 //===- Writer.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_WRITER_H
 #define LLD_COFF_WRITER_H
 
 #include "Chunks.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Object/COFF.h"
+#include <chrono>
 #include <cstdint>
 #include <vector>
 
 namespace lld {
 namespace coff {
 static const int PageSize = 4096;
 
 void writeResult();

COFF/Writer.cpp

 #include "DLL.h"
 #include "InputFiles.h"
 #include "MapFile.h"
 #include "PDB.h"
 #include "SymbolTable.h"
 #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"
 #include "llvm/Support/BinaryStreamReader.h"
 #include "llvm/Support/Debug.h"
 #include "llvm/Support/Endian.h"
 #include "llvm/Support/FileOutputBuffer.h"
 #include "llvm/Support/Parallel.h"
private:
   uint64_t SizeOfImage;
   uint64_t SizeOfHeaders;
 };
 } // anonymous namespace
 
 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) {
   Header.VirtualAddress = RVA;
   for (Chunk *C : Chunks)
     C->setRVA(C->getRVA() + RVA);
 }
 
if (ExistingDI->Signature.CVSignature != OMF::Signature::PDB70)
       return None;
     return *ExistingDI;
   }
   return None;
 }
 
 // The main function of the writer.
 void Writer::run() {
+  ScopedTimer T1(CodeLayoutTimer);
+
   createSections();
   createMiscChunks();
   createImportTables();
   createExportTable();
   if (Config->Relocatable)
     createSection(".reloc");
   assignAddresses();
   removeEmptySections();
if (Config->is64()) {
     writeHeader<pe32plus_header>();
   } else {
     writeHeader<pe32_header>();
   }
   writeSections();
   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)));
 }
 
 static StringRef getOutputSection(StringRef Name) {
   StringRef S = Name.split('$').first;
 
   // Treat a later period as a separator for MinGW, for sections like

Common/CMakeLists.txt

 if(NOT LLD_BUILT_STANDALONE)
   set(tablegen_deps intrinsics_gen)
 endif()
 
 add_lld_library(lldCommon
   Args.cpp
   ErrorHandler.cpp
   Memory.cpp
   Reproduce.cpp
   Strings.cpp
   TargetOptionsCommandFlags.cpp
   Threads.cpp
+  Timer.cpp
   Version.cpp
 
   ADDITIONAL_HEADER_DIRS
   ${LLD_INCLUDE_DIR}/lld/Common
 
   LINK_COMPONENTS
   Codegen
   Core

Common/Timer.cpp

+#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<double>(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<std::chrono::duration<double, std::milli>>(
+             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%5d ms (%5.1f%%)", S.c_str(), (int)millis(), P);
+
+  message(Str);
+
+  if (Recurse) {
+    for (const auto &Child : Children)
+      Child->print(Depth + 1, TotalDuration);
+  }
+}

include/lld/Common/Timer.h

+//===- 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 <assert.h>
+#include <chrono>
+#include <map>
+#include <memory>
+
+namespace lld {
+
+class Timer;
+
+struct ScopedTimer {
+  explicit ScopedTimer(Timer &T);
+
+  ~ScopedTimer();
+
+  void stop();
+
+  Timer *T = nullptr;
+};
+
+class Timer {
+public:
+  Timer(llvm::StringRef Name, Timer &Parent);
+
+  static Timer &root();
+
+  void start();
+  void stop();
+  void print();
+
+  double millis() const;
+
+private:
+  explicit Timer(llvm::StringRef Name);
+  void print(int Depth, double TotalDuration, bool Recurse = true) const;
+
+  std::chrono::time_point<std::chrono::high_resolution_clock> StartTime;
+  std::chrono::nanoseconds Total;
+  std::vector<Timer *> Children;
+  std::string Name;
+  Timer *Parent;
+};
+
+} // namespace lld
+
+#endif