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

[Brian Gesiak via Phabricator via cfe-commits]

modocache abandoned this revision.
modocache added inline comments.



Comment at: include/clang/Lex/PreprocessorOptions.h:165
 public:
-  PreprocessorOptions() : UsePredefines(true), DetailedRecord(false),
+  PreprocessorOptions() : PPTimer("preprocessor", "Preprocessing"),
+  UsePredefines(true),

avt77 wrote:
> modocache wrote:
> > eduardo-elizondo wrote:
> > > Should this be named "Lexing Time" or "Lexing" instead of "Preprocessing"?
> > Good idea! Now that the timer's being started up in the `Preprocessor::Lex` 
> > method, it probably should be named "Lexing". Alternatively, I could move 
> > this into, say,` Lexer::Lex`. I guess there's not much of a distinction in 
> > Clang between "lexing" and "preprocessing."
> > 
> > I had originally picked this name because that's what appears in `gcc 
> > -ftime-report`, but I guess we don't need to keep the names the same.
> Preprocessing does not means lexing. It includes much more, for example, file 
> inclusion, include pathes elaboration, macros expansion, etc. We could merge 
> all these parts or we could output the info for evey single piece. In any 
> case I think we need a group of timers related to frontend (or maybe several 
> groups: for pp, parser, Sema, codegen...). And maybe we need special switches 
> to disable/enable the groups (-ftime-report could be used as some super 
> switch for all of them). As result we need some repository of the timers and 
> most probably this repository should be kept in PreprocessorOpts.
> 
> If there are no objections I can take this job on me and come up with new 
> more general version of the patch. If it's OK then I'd like to collect the 
> proposes about the required details of the time profile: what exactly we'd 
> like to see in output? We have gcc output as an initial example but maybe we 
> need more (or less) details?
> If there are no objections I can take this job on me and come up with new 
> more general version of the patch. If it's OK then I'd like to collect the 
> proposes about the required details of the time profile: what exactly we'd 
> like to see in output? We have gcc output as an initial example but maybe we 
> need more (or less) details?

Yes, absolutely! This sounds fantastic, thank you for doing this work.

I'll abandon this diff so it doesn't clog up anyone else's review queues. 
Thanks again!


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: [time-report] Add preprocessor timer

[Andrew V. Tischenko via Phabricator via cfe-commits]

avt77 added inline comments.



Comment at: include/clang/Lex/PreprocessorOptions.h:165
 public:
-  PreprocessorOptions() : UsePredefines(true), DetailedRecord(false),
+  PreprocessorOptions() : PPTimer("preprocessor", "Preprocessing"),
+  UsePredefines(true),

modocache wrote:
> eduardo-elizondo wrote:
> > Should this be named "Lexing Time" or "Lexing" instead of "Preprocessing"?
> Good idea! Now that the timer's being started up in the `Preprocessor::Lex` 
> method, it probably should be named "Lexing". Alternatively, I could move 
> this into, say,` Lexer::Lex`. I guess there's not much of a distinction in 
> Clang between "lexing" and "preprocessing."
> 
> I had originally picked this name because that's what appears in `gcc 
> -ftime-report`, but I guess we don't need to keep the names the same.
Preprocessing does not means lexing. It includes much more, for example, file 
inclusion, include pathes elaboration, macros expansion, etc. We could merge 
all these parts or we could output the info for evey single piece. In any case 
I think we need a group of timers related to frontend (or maybe several groups: 
for pp, parser, Sema, codegen...). And maybe we need special switches to 
disable/enable the groups (-ftime-report could be used as some super switch for 
all of them). As result we need some repository of the timers and most probably 
this repository should be kept in PreprocessorOpts.

If there are no objections I can take this job on me and come up with new more 
general version of the patch. If it's OK then I'd like to collect the proposes 
about the required details of the time profile: what exactly we'd like to see 
in output? We have gcc output as an initial example but maybe we need more (or 
less) details?



Comment at: lib/Lex/Preprocessor.cpp:746
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+

vsk wrote:
> MatzeB wrote:
> > modocache wrote:
> > > erik.pilkington wrote:
> > > > Doesn't this just start a timer and immediately end the timer? 
> > > > Shouldn't we do: `llvm::TimeRegion LexTime(PPOpts->getTimer())` so that 
> > > > the dtor gets called when this function returns and we track the time 
> > > > spent in this function?
> > > > 
> > > > Also: this is a pretty hot function, and it looks like TimeRegion does 
> > > > some non-trivial work if time is being tracked. Have you tried testing 
> > > > this on a big c++ file with and without this patch and seeing what the 
> > > > difference in compile time looks like?
> > > Ah, yes you're right! Sorry about that. Actually keeping the timer alive 
> > > for the duration of the method also reveals that the method is called 
> > > recursively, which causes an assert, because timers can't be started 
> > > twice.
> > > 
> > > Another spot in Clang works around this with a "reference counted" timer: 
> > > https://github.com/llvm-mirror/clang/blob/6ac9c51ede0a50cca13dd4ac03562c036f7a3f48/lib/CodeGen/CodeGenAction.cpp#L130-L134.
> > >  I have a more generic version of this "reference counting timer" that 
> > > I've been using for some of the other timers I've been adding; maybe I'll 
> > > use it here as well.
> > FWIF: I share Eriks concerns about compiletime. Timers are enabled in 
> > optimized builds, and querying them is not free. So putting one into a 
> > function that is called a lot and is time critical seems like a bad idea 
> > (do benchmarking to prove or disprove this!).
> The  timer is not started or queried unless -ftime-report is enabled. In the 
> common case the overhead amounts to one extra null-check. And when we're 
> collecting timing information, some performance degradation (say, within 5%) 
> should be acceptable. I agree that we should get a sense for what the 
> overhead is, but am not convinced that this should be a blocking issue.
Here we have more than "one extra null-check": we're dealing with 
constructor/destructor as well (and it's for every Lex()). I agree that it 
should be acceptable for us but we have to profile it (maybe we should not 
profile Lex() but something above it). 



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: [time-report] Add preprocessor timer

[Vedant Kumar via Phabricator via cfe-commits]

vsk added inline comments.



Comment at: lib/Lex/Preprocessor.cpp:746
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+

MatzeB wrote:
> modocache wrote:
> > erik.pilkington wrote:
> > > Doesn't this just start a timer and immediately end the timer? Shouldn't 
> > > we do: `llvm::TimeRegion LexTime(PPOpts->getTimer())` so that the dtor 
> > > gets called when this function returns and we track the time spent in 
> > > this function?
> > > 
> > > Also: this is a pretty hot function, and it looks like TimeRegion does 
> > > some non-trivial work if time is being tracked. Have you tried testing 
> > > this on a big c++ file with and without this patch and seeing what the 
> > > difference in compile time looks like?
> > Ah, yes you're right! Sorry about that. Actually keeping the timer alive 
> > for the duration of the method also reveals that the method is called 
> > recursively, which causes an assert, because timers can't be started twice.
> > 
> > Another spot in Clang works around this with a "reference counted" timer: 
> > https://github.com/llvm-mirror/clang/blob/6ac9c51ede0a50cca13dd4ac03562c036f7a3f48/lib/CodeGen/CodeGenAction.cpp#L130-L134.
> >  I have a more generic version of this "reference counting timer" that I've 
> > been using for some of the other timers I've been adding; maybe I'll use it 
> > here as well.
> FWIF: I share Eriks concerns about compiletime. Timers are enabled in 
> optimized builds, and querying them is not free. So putting one into a 
> function that is called a lot and is time critical seems like a bad idea (do 
> benchmarking to prove or disprove this!).
The  timer is not started or queried unless -ftime-report is enabled. In the 
common case the overhead amounts to one extra null-check. And when we're 
collecting timing information, some performance degradation (say, within 5%) 
should be acceptable. I agree that we should get a sense for what the overhead 
is, but am not convinced that this should be a blocking issue.


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: [time-report] Add preprocessor timer

[Matthias Braun via Phabricator via cfe-commits]

MatzeB added inline comments.



Comment at: lib/Lex/Preprocessor.cpp:746
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+

modocache wrote:
> erik.pilkington wrote:
> > Doesn't this just start a timer and immediately end the timer? Shouldn't we 
> > do: `llvm::TimeRegion LexTime(PPOpts->getTimer())` so that the dtor gets 
> > called when this function returns and we track the time spent in this 
> > function?
> > 
> > Also: this is a pretty hot function, and it looks like TimeRegion does some 
> > non-trivial work if time is being tracked. Have you tried testing this on a 
> > big c++ file with and without this patch and seeing what the difference in 
> > compile time looks like?
> Ah, yes you're right! Sorry about that. Actually keeping the timer alive for 
> the duration of the method also reveals that the method is called 
> recursively, which causes an assert, because timers can't be started twice.
> 
> Another spot in Clang works around this with a "reference counted" timer: 
> https://github.com/llvm-mirror/clang/blob/6ac9c51ede0a50cca13dd4ac03562c036f7a3f48/lib/CodeGen/CodeGenAction.cpp#L130-L134.
>  I have a more generic version of this "reference counting timer" that I've 
> been using for some of the other timers I've been adding; maybe I'll use it 
> here as well.
FWIF: I share Eriks concerns about compiletime. Timers are enabled in optimized 
builds, and querying them is not free. So putting one into a function that is 
called a lot and is time critical seems like a bad idea (do benchmarking to 
prove or disprove this!).


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: [time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache added inline comments.



Comment at: include/clang/Lex/PreprocessorOptions.h:165
 public:
-  PreprocessorOptions() : UsePredefines(true), DetailedRecord(false),
+  PreprocessorOptions() : PPTimer("preprocessor", "Preprocessing"),
+  UsePredefines(true),

eduardo-elizondo wrote:
> Should this be named "Lexing Time" or "Lexing" instead of "Preprocessing"?
Good idea! Now that the timer's being started up in the `Preprocessor::Lex` 
method, it probably should be named "Lexing". Alternatively, I could move this 
into, say,` Lexer::Lex`. I guess there's not much of a distinction in Clang 
between "lexing" and "preprocessing."

I had originally picked this name because that's what appears in `gcc 
-ftime-report`, but I guess we don't need to keep the names the same.


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: [time-report] Add preprocessor timer

[Eddie Elizondo via Phabricator via cfe-commits]

eduardo-elizondo added inline comments.



Comment at: include/clang/Lex/PreprocessorOptions.h:165
 public:
-  PreprocessorOptions() : UsePredefines(true), DetailedRecord(false),
+  PreprocessorOptions() : PPTimer("preprocessor", "Preprocessing"),
+  UsePredefines(true),

Should this be named "Lexing Time" or "Lexing" instead of "Preprocessing"?


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: [time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache planned changes to this revision.
modocache added inline comments.



Comment at: lib/Lex/Preprocessor.cpp:746
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+

erik.pilkington wrote:
> Doesn't this just start a timer and immediately end the timer? Shouldn't we 
> do: `llvm::TimeRegion LexTime(PPOpts->getTimer())` so that the dtor gets 
> called when this function returns and we track the time spent in this 
> function?
> 
> Also: this is a pretty hot function, and it looks like TimeRegion does some 
> non-trivial work if time is being tracked. Have you tried testing this on a 
> big c++ file with and without this patch and seeing what the difference in 
> compile time looks like?
Ah, yes you're right! Sorry about that. Actually keeping the timer alive for 
the duration of the method also reveals that the method is called recursively, 
which causes an assert, because timers can't be started twice.

Another spot in Clang works around this with a "reference counted" timer: 
https://github.com/llvm-mirror/clang/blob/6ac9c51ede0a50cca13dd4ac03562c036f7a3f48/lib/CodeGen/CodeGenAction.cpp#L130-L134.
 I have a more generic version of this "reference counting timer" that I've 
been using for some of the other timers I've been adding; maybe I'll use it 
here as well.


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: [time-report] Add preprocessor timer

[Erik Pilkington via Phabricator via cfe-commits]

erik.pilkington added a comment.

This looks really usefull, thanks for working on this!




Comment at: lib/Lex/Preprocessor.cpp:746
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+

Doesn't this just start a timer and immediately end the timer? Shouldn't we do: 
`llvm::TimeRegion LexTime(PPOpts->getTimer())` so that the dtor gets called 
when this function returns and we track the time spent in this function?

Also: this is a pretty hot function, and it looks like TimeRegion does some 
non-trivial work if time is being tracked. Have you tried testing this on a big 
c++ file with and without this patch and seeing what the difference in compile 
time looks like?


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: [time-report] Add preprocessor timer

[Vedant Kumar via Phabricator via cfe-commits]

vsk accepted this revision.
vsk added a comment.
This revision is now accepted and ready to land.

LGTM.


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: [time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache added a comment.

Friendly ping! I think this is ready to be reviewed. It adds an additional row, 
`Preprocessing`, to the `Miscellaneous Ungrouped Timers` section of the `clang 
-ftime-report` output:

  
===-===
   Miscellaneous Ungrouped Timers
  
===-===
  
 ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- 
Name ---
 0.0360 ( 17.8%)   0.0060 ( 35.3%)   0.0420 ( 19.2%)   0.3440 ( 50.6%)  
Code Generation Time
 0.0390 ( 19.3%)   0.0050 ( 29.4%)   0.0440 ( 20.1%)   0.1734 ( 25.5%)  
LLVM IR Generation Time
 0.1270 ( 62.9%)   0.0060 ( 35.3%)   0.1330 ( 60.7%)   0.1622 ( 23.9%)  
Preprocessing
 0.2020 (100.0%)   0.0170 (100.0%)   0.2190 (100.0%)   0.6796 (100.0%)  
Total

Grouping these timers is something I'd like to explore in future commits.


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: [time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

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

Oops, sorry, didn't mean to remove the subscribers. `arc diff --verbatim` 
strikes again.


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: [time-report] Add preprocessor timer

[Brian Gesiak via Phabricator via cfe-commits]

modocache updated this revision to Diff 95.
modocache retitled this revision from "[RFC][time-report] Add preprocessor 
timer" to "[time-report] Add preprocessor timer".
modocache edited the summary of this revision.
modocache removed subscribers: vsk, mzolotukhin.
modocache added a comment.

Add `PreprocessorOptions::getTimer`, and move the timer to the top of 
`Preprocessor::Lex()`.


https://reviews.llvm.org/D36492

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


Index: lib/Lex/Preprocessor.cpp
===
--- lib/Lex/Preprocessor.cpp
+++ lib/Lex/Preprocessor.cpp
@@ -743,6 +743,8 @@
 }
 
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+
   // We loop here until a lex function returns a token; this avoids recursion.
   bool ReturnedToken;
   do {
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
@@ -14,6 +14,7 @@
 #include "llvm/ADT/IntrusiveRefCntPtr.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/ADT/StringSet.h"
+#include "llvm/Support/Timer.h"
 #include 
 #include 
 #include 
@@ -37,10 +38,11 @@
   /// \brief libstdc++
   ARCXX_libstdcxx
 };
-  
+
 /// PreprocessorOptions - This class is used for passing the various options
 /// used in preprocessor initialization to InitializePreprocessor().
 class PreprocessorOptions {
+  llvm::Timer PPTimer;
 public:
   std::vector > Macros;
   std::vector Includes;
@@ -127,7 +129,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
+  /// preprocessing. This flag defaults to false.
+  bool ShowTimers;
+
   /// \brief The Objective-C++ ARC standard library that we should support,
   /// by providing appropriate definitions to retrofit the standard library
   /// with support for lifetime-qualified pointers.
@@ -156,14 +162,17 @@
   std::shared_ptr FailedModules;
 
 public:
-  PreprocessorOptions() : UsePredefines(true), DetailedRecord(false),
+  PreprocessorOptions() : PPTimer("preprocessor", "Preprocessing"),
+  UsePredefines(true),
+  DetailedRecord(false),
   DisablePCHValidation(false),
   AllowPCHWithCompilerErrors(false),
   DumpDeserializedPCHDecls(false),
   PrecompiledPreambleBytes(0, true),
   GeneratePreamble(false),
   RemappedFilesKeepOriginalName(true),
   RetainRemappedFileBuffers(false),
+  ShowTimers(false),
   ObjCXXARCStandardLibrary(ARCXX_nolib) { }
 
   void addMacroDef(StringRef Name) { Macros.emplace_back(Name, false); }
@@ -197,6 +206,10 @@
 PrecompiledPreambleBytes.first = 0;
 PrecompiledPreambleBytes.second = 0;
   }
+
+  llvm::Timer *getTimer() {
+return ShowTimers ?  : nullptr;
+  }
 };
 
 } // end namespace clang


Index: lib/Lex/Preprocessor.cpp
===
--- lib/Lex/Preprocessor.cpp
+++ lib/Lex/Preprocessor.cpp
@@ -743,6 +743,8 @@
 }
 
 void Preprocessor::Lex(Token ) {
+  llvm::TimeRegion(PPOpts->getTimer());
+
   // We loop here until a lex function returns a token; this avoids recursion.
   bool ReturnedToken;
   do {
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
===