[PATCH] D41915: [lldCOFF] Print detailed timing information with /VERBOSE

[Rui Ueyama via Phabricator via llvm-commits]

ruiu added inline comments.


================
Comment at: lld/COFF/Timing.h:17
+namespace coff {
+enum TimingPhases {
+  TP_Total,
----------------
zturner wrote:
> ruiu wrote:
> > 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.
> 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.
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.


================
Comment at: lld/Common/Timer.cpp:34
+  // <indent>name:<padding for alignment>
+  message(formatv("{0}({1,+6}%) {2:ms}",
+                  fmt_pad(Name + ":", LI, RI), // <indent>name:<padding>
----------------
zturner wrote:
> ruiu wrote:
> > 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.
> 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.
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



================
Comment at: lld/Common/Timer.cpp:103
+
+int Timer::calculateNameFieldWidth(int Depth, const TimerPhase &Phase) const {
+  // indentation, then name, then a colon and a space.
----------------
zturner wrote:
> ruiu wrote:
> > 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.
> 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"?
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



https://reviews.llvm.org/D41915