[PATCH] D36492: [RFC][time-report] Add preprocessor timer

[Michael Zolotukhin via Phabricator via cfe-commits]

mzolotukhin added a comment.

FWIW, I strongly support the idea of adding more detailed timers into the 
frontend. Thanks for working on it!
I probably won't be very helpful in reviewing this code, but I'd appreciate if 
you CC me in the future patches.

Thanks,
Michael


https://reviews.llvm.org/D36492



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D36492: [RFC][time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache added a reviewer: vsk.
modocache planned changes to this revision.
modocache added a comment.

Thanks for the feedback, @vsk, I really appreciate it! I have some other work 
done for this on my local checkout, but I was going a little bonkers working on 
it without knowing whether people would want it merged or not. I'll update this 
with your feedback and upload the rest for review as well.

> It'd be nice to dump this timer from Preprocessor::PrintStats(), too.

Good idea, will do!




Comment at: lib/Lex/Preprocessor.cpp:660
 
+  llvm::TimeRegion(PPOpts->ShowTimers ?  : nullptr);
+

vsk wrote:
> vsk wrote:
> > I wonder whether this is too fine-grained. I think setting up a timer in 
> > Preprocessor::Lex() might capture more information. Would you mind 
> > experimenting with that?
> Nitpick: it may be useful to add PPOpts::getTimer(), in case we find more 
> sites where we need to either get back the PP timer or nullptr.
> I think setting up a timer in `Preprocessor::Lex()` might capture more 
> information.

Yes, can do! As it happens, the timers in this current diff cover all of the 
event counters that are incremented and then printed in  
`Preprocessor::PrintStats()`, except two: `NumTokenPaste` and 
`NumFastTokenPaste`. Beginning the timer in the Lexer would allow me to measure 
the time it takes to do token pasting as well, so I think this is a great idea. 
Thanks!

> it may be useful to add `PPOpts::getTimer()`

Agreed, will do!


https://reviews.llvm.org/D36492



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D36492: [RFC][time-report] Add preprocessor timer

[Vedant Kumar via Phabricator via cfe-commits]

vsk added subscribers: mzolotukhin, vsk.
vsk added a comment.

Thanks for working on this. Collecting better timing information in the 
frontend sgtm. It's cheap to do, and we can use the information to guide our 
efforts re: attacking the compile-time problem. Feel free to add me to future 
timing-related reviews. Regarding this specific patch:

Could you add a short test (perhaps in test/Misc?) that checks that 
-ftime-report prints out an entry for 'Preprocessing'?

It'd be nice to dump this timer from Preprocessor::PrintStats(), too.




Comment at: lib/Lex/Preprocessor.cpp:660
 
+  llvm::TimeRegion(PPOpts->ShowTimers ?  : nullptr);
+

I wonder whether this is too fine-grained. I think setting up a timer in 
Preprocessor::Lex() might capture more information. Would you mind 
experimenting with that?



Comment at: lib/Lex/Preprocessor.cpp:660
 
+  llvm::TimeRegion(PPOpts->ShowTimers ?  : nullptr);
+

vsk wrote:
> I wonder whether this is too fine-grained. I think setting up a timer in 
> Preprocessor::Lex() might capture more information. Would you mind 
> experimenting with that?
Nitpick: it may be useful to add PPOpts::getTimer(), in case we find more sites 
where we need to either get back the PP timer or nullptr.


https://reviews.llvm.org/D36492



___
cfe-commits mailing list
cfe-commits@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/cfe-commits

[PATCH] D36492: [RFC][time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache created this revision.

`gcc -ftime-report` provides a breakdown of how much time GCC spends
doing preprocessing, parsing, template instantiation, and more:

  g++ -ftime-report foo.cpp
  Execution times (seconds)
   phase setup :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.00 ( 0%) 
wall1414 kB ( 8%) ggc
   phase parsing   :   0.10 (100%) usr   0.08 (100%) sys   0.18 (95%) 
wall   15955 kB (88%) ggc
   phase opt and generate  :   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 5%) 
wall 489 kB ( 3%) ggc
   |name lookup:   0.00 ( 0%) usr   0.00 ( 0%) sys   0.04 (21%) 
wall1054 kB ( 6%) ggc
   preprocessing   :   0.02 (20%) usr   0.01 (13%) sys   0.03 (16%) 
wall 896 kB ( 5%) ggc
   parser (global) :   0.00 ( 0%) usr   0.03 (38%) sys   0.04 (21%) 
wall6603 kB (37%) ggc
   parser struct body  :   0.04 (40%) usr   0.00 ( 0%) sys   0.04 (21%) 
wall2791 kB (15%) ggc
   parser enumerator list  :   0.01 (10%) usr   0.00 ( 0%) sys   0.00 ( 0%) 
wall  44 kB ( 0%) ggc
   parser function body:   0.00 ( 0%) usr   0.02 (25%) sys   0.02 (11%) 
wall1047 kB ( 6%) ggc
   parser inl. meth. body  :   0.01 (10%) usr   0.01 (13%) sys   0.03 (16%) 
wall1093 kB ( 6%) ggc
   template instantiation  :   0.02 (20%) usr   0.01 (12%) sys   0.02 (11%) 
wall3280 kB (18%) ggc
   LRA non-specific:   0.00 ( 0%) usr   0.00 ( 0%) sys   0.01 ( 5%) 
wall   0 kB ( 0%) ggc
   TOTAL :   0.10 0.08 0.19 
 18028 kB

`clang -ftime-report` gives an incredibly detailed breakdown of how long
each LLVM pass takes, but when it comes to front-end times, only
provides the generic "Clang front-end timer", or "Code Generation Time".
Here's an example of its output:
https://gist.github.com/modocache/d74833818107ed50d11387a5a4e3fb72

As a result, when attempting to diagnose slow compile times with Clang,
users are forced to use external profiling tools in order to determine
whether the bottleneck is in parsing, template instantiation, or LLVM.

This diff adds the first of several timers that aim to match
`gcc -ftime-report`: a timer that outputs the amount of time spent in the Clang
preprocessor.

I'm curious whether Clang maintainers think this timer is useful, and whether
there's interest in adding more timers, especially around the Clang parser.


https://reviews.llvm.org/D36492

Files:
  include/clang/Lex/Preprocessor.h
  include/clang/Lex/PreprocessorOptions.h
  lib/Frontend/CompilerInstance.cpp
  lib/Lex/PPDirectives.cpp
  lib/Lex/Preprocessor.cpp


Index: lib/Lex/Preprocessor.cpp
===
--- lib/Lex/Preprocessor.cpp
+++ lib/Lex/Preprocessor.cpp
@@ -88,6 +88,7 @@
   CurDirLookup(nullptr), CurLexerKind(CLK_Lexer),
   CurLexerSubmodule(nullptr), Callbacks(nullptr),
   CurSubmoduleState(), MacroArgCache(nullptr),
+  PreprocessingTimer("preprocessor", "Preprocessing"),
   Record(nullptr), MIChainHead(nullptr) {
   OwnsHeaderSearch = OwnsHeaders;
   
@@ -656,6 +657,8 @@
 
   IdentifierInfo  = *Identifier.getIdentifierInfo();
 
+  llvm::TimeRegion(PPOpts->ShowTimers ?  : nullptr);
+
   // If the information about this identifier is out of date, update it from
   // the external source.
   // We have to treat __VA_ARGS__ in a special way, since it gets
Index: lib/Lex/PPDirectives.cpp
===
--- lib/Lex/PPDirectives.cpp
+++ lib/Lex/PPDirectives.cpp
@@ -871,6 +871,8 @@
 /// lexer/preprocessor state, and advances the lexer(s) so that the next token
 /// read is the correct one.
 void Preprocessor::HandleDirective(Token ) {
+  llvm::TimeRegion(PPOpts->ShowTimers ?  : nullptr);
+
   // FIXME: Traditional: # with whitespace before it not recognized by K?
 
   // We just parsed a # character at the start of a line, so we're in directive
Index: lib/Frontend/CompilerInstance.cpp
===
--- lib/Frontend/CompilerInstance.cpp
+++ lib/Frontend/CompilerInstance.cpp
@@ -367,7 +367,9 @@
 // Preprocessor
 
 void CompilerInstance::createPreprocessor(TranslationUnitKind TUKind) {
-  const PreprocessorOptions  = getPreprocessorOpts();
+  PreprocessorOptions  = getPreprocessorOpts();
+  if (getFrontendOpts().ShowTimers)
+PPOpts.ShowTimers = true;
 
   // Create a PTH manager if we are using some form of a token cache.
   PTHManager *PTHMgr = nullptr;
Index: include/clang/Lex/PreprocessorOptions.h
===
--- include/clang/Lex/PreprocessorOptions.h
+++ include/clang/Lex/PreprocessorOptions.h
@@ -127,7 +127,11 @@
   /// manipulation of the compiler invocation object, in cases where the 
   /// compiler invocation and its buffers will be reused.
   bool RetainRemappedFileBuffers;
-  
+
+  /// \brief Whether to measure the amount of time spent in code related to
+  ///