Make -ftime-report produce a coarse breakdown of compilation phases

I'm adding this because I would like to use it to profile clang over large project builds.  My plan is to thread -ftime-report through the build system and write a script to aggregate the output.

Output looks like this for a hello world test case:

$ Debug/bin/clang -ftime-report t.c -c -o t.o
...

===-------------------------------------------------------------------------===
                            Compilation phase timers
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0360 seconds (0.0497 wall clock)

   ---User Time---   --User+System--   ---Wall Time---  --- Name ---
   0.0160 ( 44.4%)   0.0160 ( 44.4%)   0.0198 ( 39.8%)  Parsing and Sema Time
   0.0120 ( 33.3%)   0.0120 ( 33.3%)   0.0187 ( 37.6%)  Lexing and Preprocessing Time
   0.0040 ( 11.1%)   0.0040 ( 11.1%)   0.0071 ( 14.4%)  Machine Code Generation Time
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0029 (  5.8%)  LLVM IR Generation Time
   0.0040 ( 11.1%)   0.0040 ( 11.1%)   0.0012 (  2.5%)  LLVM IR Optimization Time
   0.0360 (100.0%)   0.0360 (100.0%)   0.0497 (100.0%)  Total

[Reid Kleckner, 2010-06-19 00:13:32]

Please take a look.

[daniel_zuster.org, 2010-06-23 05:24:07]

Hi Reid,

I don't see any changes in Preprocessor.h other than to add #includes,
was that intentional?

Have you measured the impact of your changes on performance? I suspect
that is going to be prohibitive...

 - Daniel

On Fri, Jun 18, 2010 at 5:13 PM,  <reid.kleckner@gmail.com> wrote:
> Reviewers: ,
>
> Message:
> Please take a look.
>
> Description:
> I'm adding this because I would like to use it to profile clang over
> large project builds.  My plan is to thread -ftime-report through the
> build system and write a script to aggregate the output.
>
> Output looks like this for a hello world test case:
>
> $ Debug/bin/clang -ftime-report t.c -c -o t.o
> ...
>
>
===-------------------------------------------------------------------------===
>                             Compilation phase timers
>
===-------------------------------------------------------------------------===
>   Total Execution Time: 0.0360 seconds (0.0497 wall clock)
>
>    ---User Time---   --User+System--   ---Wall Time---  --- Name ---
>    0.0160 ( 44.4%)   0.0160 ( 44.4%)   0.0198 ( 39.8%)  Parsing and Sema
> Time
>    0.0120 ( 33.3%)   0.0120 ( 33.3%)   0.0187 ( 37.6%)  Lexing and
> Preprocessing Time
>    0.0040 ( 11.1%)   0.0040 ( 11.1%)   0.0071 ( 14.4%)  Machine Code
> Generation Time
>    0.0000 (  0.0%)   0.0000 (  0.0%)   0.0029 (  5.8%)  LLVM IR
> Generation Time
>    0.0040 ( 11.1%)   0.0040 ( 11.1%)   0.0012 (  2.5%)  LLVM IR
> Optimization Time
>    0.0360 (100.0%)   0.0360 (100.0%)   0.0497 (100.0%)  Total
>
>
> Please review this at http://codereview.appspot.com/1683046/show
>
> Affected files:
>   A     include/clang/Basic/PhaseTimeInfo.h
>   M     include/clang/Lex/Preprocessor.h
>   M     include/clang/Parse/Parser.h
>   M     include/clang/Sema/ParseAST.h
>   A     lib/Basic/PhaseTimeInfo.cpp
>   M     lib/CodeGen/BackendUtil.cpp
>   M     lib/CodeGen/CodeGenAction.cpp
>   M     lib/Frontend/FrontendAction.cpp
>   M     lib/Sema/ParseAST.cpp
>
>
> _______________________________________________
> cfe-commits mailing list
> cfe-commits@cs.uiuc.edu
> http://lists.cs.uiuc.edu/mailman/listinfo/cfe-commits
>

[Reid Kleckner, 2010-06-23 21:23:12]

On Tue, Jun 22, 2010 at 10:24 PM, Daniel Dunbar <daniel@zuster.org> wrote:
> Hi Reid,
>
> I don't see any changes in Preprocessor.h other than to add #includes,
> was that intentional?

No, that can be discarded.

> Have you measured the impact of your changes on performance? I suspect
> that is going to be prohibitive...

Times for building a debug llvm+clang with a Release-Asserts clang,
without -ftime-report enabled:

Trunk:
real	5m53.240s
user	20m7.335s
sys	1m33.862s

With timers:
real	5m57.742s
user	20m20.052s
sys	1m34.406s

So, it's a 1.25% slowdown.  I don't know if that's in the noise margin
or not.  I didn't repeat the experiment because it takes 12 minutes
and I can't do any other major computational tasks while it's running.

One other drawback to this whole approach is that I'm missing ~17% of
the time spent in the clang -cc1 invocation, and I can't find where
it's coming from.  It may be better to use oprofile or some other
profile and try to break the output of that down by what directory the
source file came from.  I'm not sure how inlining interacts with what
function oprofile assigns the cost to, though, so that may misreport
the costs for the inlined lexing and preprocessing calls.

Reid