[time-trace] Add a new time trace scope variable named "ParseDeclarationOrFunctionDefinition". #65268

MaggieYingYi · 2023-09-04T15:07:16Z

When profiling code using -ftime-trace with the default time-trace-granularity value (500 microseconds), in some code there is a large empty timeline in the flame chart profiling view (using Chrome Tracing view). If you pass -ftime-trace-granularity=0 in order to show all time traces, the empty timeline consists of a large number of small time scopes named EvaluateAsConstExpr. This change adds an enclosing time trace scope for the function Parser::ParseDeclarationOrFunctionDefinition to record the time spent parsing the function's declaration or definition.

MaggieYingYi · 2023-09-12T15:31:38Z

Gentle ping ...

rnk

This seems fine to me, but it's hard to understand if this is redundant with some other "ParseFunction" scope from the tests. WDYT @MaskRay ?

MaskRay · 2023-09-20T00:44:12Z

This seems fine to me, but it's hard to understand if this is redundant with some other "ParseFunction" scope from the tests. WDYT @MaskRay ?

I share similar concern but I am not familiar with the parser...
@AaronBallman

MaggieYingYi · 2023-09-27T07:22:29Z

Gentle ping ...

AaronBallman

Apologies on the delayed review! Thank you for working on this; we really could use better time trace output in Clang to start helping us get a better handle on improving compile time performance.

clang/lib/Parse/Parser.cpp

llvmbot · 2023-10-12T13:29:30Z

@llvm/pr-subscribers-clang

@llvm/pr-subscribers-clang-driver

Author: None (MaggieYingYi)

Changes

When profiling code using -ftime-trace with the default time-trace-granularity value (500 microseconds), in some code there is a large empty timeline in the flame chart profiling view (using Chrome Tracing view). If you pass -ftime-trace-granularity=0 in order to show all time traces, the empty timeline consists of a large number of small time scopes named EvaluateAsConstExpr. This change adds an enclosing time trace scope for the function Parser::ParseDeclarationOrFunctionDefinition to record the time spent parsing the function's declaration or definition.

Full diff: https://github.com/llvm/llvm-project/pull/65268.diff

3 Files Affected:

(modified) clang/lib/Parse/Parser.cpp (+9-1)
(added) clang/test/Driver/check-time-trace-ParseDeclarationOrFunctionDefinition.cpp (+14)
(modified) clang/unittests/Support/TimeProfilerTest.cpp (+26-18)

diff --git a/clang/lib/Parse/Parser.cpp b/clang/lib/Parse/Parser.cpp
index 0f930248e77174b..533a9af173178b0 100644
--- a/clang/lib/Parse/Parser.cpp
+++ b/clang/lib/Parse/Parser.cpp
@@ -13,8 +13,8 @@
 #include "clang/Parse/Parser.h"
 #include "clang/AST/ASTConsumer.h"
 #include "clang/AST/ASTContext.h"
-#include "clang/AST/DeclTemplate.h"
 #include "clang/AST/ASTLambda.h"
+#include "clang/AST/DeclTemplate.h"
 #include "clang/Basic/FileManager.h"
 #include "clang/Parse/ParseDiagnostic.h"
 #include "clang/Parse/RAIIObjectsForParser.h"
@@ -22,6 +22,7 @@
 #include "clang/Sema/ParsedTemplate.h"
 #include "clang/Sema/Scope.h"
 #include "llvm/Support/Path.h"
+#include "llvm/Support/TimeProfiler.h"
 using namespace clang;
 
 
@@ -1229,6 +1230,9 @@ Parser::DeclGroupPtrTy Parser::ParseDeclOrFunctionDefInternal(
 Parser::DeclGroupPtrTy Parser::ParseDeclarationOrFunctionDefinition(
     ParsedAttributes &Attrs, ParsedAttributes &DeclSpecAttrs,
     ParsingDeclSpec *DS, AccessSpecifier AS) {
+  // Add an enclosing time trace scope for a bunch of small scopes with
+  // "EvaluateAsConstExpr".
+  llvm::TimeTraceScope TimeScope("ParseDeclarationOrFunctionDefinition");
   if (DS) {
     return ParseDeclOrFunctionDefInternal(Attrs, DeclSpecAttrs, *DS, AS);
   } else {
@@ -1259,6 +1263,10 @@ Parser::DeclGroupPtrTy Parser::ParseDeclarationOrFunctionDefinition(
 Decl *Parser::ParseFunctionDefinition(ParsingDeclarator &D,
                                       const ParsedTemplateInfo &TemplateInfo,
                                       LateParsedAttrList *LateParsedAttrs) {
+  llvm::TimeTraceScope TimeScope(
+      "ParseFunctionDefinition",
+      Actions.GetNameForDeclarator(D).getName().getAsString());
+
   // Poison SEH identifiers so they are flagged as illegal in function bodies.
   PoisonSEHIdentifiersRAIIObject PoisonSEHIdentifiers(*this, true);
   const DeclaratorChunk::FunctionTypeInfo &FTI = D.getFunctionTypeInfo();
diff --git a/clang/test/Driver/check-time-trace-ParseDeclarationOrFunctionDefinition.cpp b/clang/test/Driver/check-time-trace-ParseDeclarationOrFunctionDefinition.cpp
new file mode 100644
index 000000000000000..96bb37d57823e8b
--- /dev/null
+++ b/clang/test/Driver/check-time-trace-ParseDeclarationOrFunctionDefinition.cpp
@@ -0,0 +1,14 @@
+// RUN: %clangxx -S -ftime-trace -ftime-trace-granularity=0 -o %T/check-time-trace-ParseDeclarationOrFunctionDefinition %s
+// RUN: cat %T/check-time-trace-ParseDeclarationOrFunctionDefinition.json \
+// RUN:   | %python -c 'import json, sys; json.dump(json.loads(sys.stdin.read()), sys.stdout, sort_keys=True, indent=2)' \
+// RUN:   | FileCheck %s
+
+// CHECK-DAG: "name": "ParseDeclarationOrFunctionDefinition"
+// CHECK-DAG: "name": "ParseFunctionDefinition"
+// CHECK-DAG: "detail": "foo"
+// CHECK-DAG: "name": "ParseFunctionDefinition"
+// CHECK-DAG: "detail": "bar"
+
+template <typename T>
+void foo(T) {}
+void bar() { foo(0); }
diff --git a/clang/unittests/Support/TimeProfilerTest.cpp b/clang/unittests/Support/TimeProfilerTest.cpp
index a7ca2bf91e474ef..f69a54692b0072a 100644
--- a/clang/unittests/Support/TimeProfilerTest.cpp
+++ b/clang/unittests/Support/TimeProfilerTest.cpp
@@ -177,22 +177,29 @@ constexpr int slow_init_list[] = {1, 1, 2, 3, 5, 8, 13, 21}; // 25th line
   std::string TraceGraph = buildTraceGraph(Json);
   ASSERT_TRUE(TraceGraph == R"(
 Frontend
-| EvaluateAsRValue (<test.cc:8:21>)
-| EvaluateForOverflow (<test.cc:8:21, col:25>)
-| EvaluateForOverflow (<test.cc:8:30, col:32>)
-| EvaluateAsRValue (<test.cc:9:14>)
-| EvaluateForOverflow (<test.cc:9:9, col:14>)
-| isPotentialConstantExpr (slow_namespace::slow_func)
-| EvaluateAsBooleanCondition (<test.cc:8:21, col:25>)
-| | EvaluateAsRValue (<test.cc:8:21, col:25>)
-| EvaluateAsBooleanCondition (<test.cc:8:21, col:25>)
-| | EvaluateAsRValue (<test.cc:8:21, col:25>)
-| EvaluateAsInitializer (slow_value)
-| EvaluateAsConstantExpr (<test.cc:17:33, col:59>)
-| EvaluateAsConstantExpr (<test.cc:18:11, col:37>)
-| EvaluateAsConstantExpr (<test.cc:23:31, col:57>)
-| EvaluateAsRValue (<test.cc:22:14, line:23:58>)
-| EvaluateAsInitializer (slow_init_list)
+| ParseDeclarationOrFunctionDefinition
+| ParseDeclarationOrFunctionDefinition
+| | ParseFunctionDefinition (slow_func)
+| | | EvaluateAsRValue (<test.cc:8:21>)
+| | | EvaluateForOverflow (<test.cc:8:21, col:25>)
+| | | EvaluateForOverflow (<test.cc:8:30, col:32>)
+| | | EvaluateAsRValue (<test.cc:9:14>)
+| | | EvaluateForOverflow (<test.cc:9:9, col:14>)
+| | | isPotentialConstantExpr (slow_namespace::slow_func)
+| | | EvaluateAsBooleanCondition (<test.cc:8:21, col:25>)
+| | | | EvaluateAsRValue (<test.cc:8:21, col:25>)
+| | | EvaluateAsBooleanCondition (<test.cc:8:21, col:25>)
+| | | | EvaluateAsRValue (<test.cc:8:21, col:25>)
+| ParseDeclarationOrFunctionDefinition
+| | ParseFunctionDefinition (slow_test)
+| | | EvaluateAsInitializer (slow_value)
+| | | EvaluateAsConstantExpr (<test.cc:17:33, col:59>)
+| | | EvaluateAsConstantExpr (<test.cc:18:11, col:37>)
+| ParseDeclarationOrFunctionDefinition
+| | EvaluateAsConstantExpr (<test.cc:23:31, col:57>)
+| | EvaluateAsRValue (<test.cc:22:14, line:23:58>)
+| ParseDeclarationOrFunctionDefinition
+| | EvaluateAsInitializer (slow_init_list)
 | PerformPendingInstantiations
 )");
 
@@ -213,8 +220,9 @@ struct {
   std::string TraceGraph = buildTraceGraph(Json);
   ASSERT_TRUE(TraceGraph == R"(
 Frontend
-| isIntegerConstantExpr (<test.c:3:18>)
-| EvaluateKnownConstIntCheckOverflow (<test.c:3:18>)
+| ParseDeclarationOrFunctionDefinition
+| | isIntegerConstantExpr (<test.c:3:18>)
+| | EvaluateKnownConstIntCheckOverflow (<test.c:3:18>)
 | PerformPendingInstantiations
 )");

MaggieYingYi · 2023-10-27T14:10:05Z

Gentle ping ...

AaronBallman

LGTM, thank you for this! Please add a release note letting users know about the improvement when you land the changes.

MaggieYingYi · 2023-10-30T14:51:01Z

Hi @AaronBallman,

Thanks for reviewing and approving the patch.

I have added a release note in the commit 014ad43. Since I haven't ever added a release note before, could you please let me know is it the correct file and the correct location to add a release note? If not, could you please give me some suggestions/links on how to add a release note?

Many thanks,
Maggie

AaronBallman

Your release note looks great, just a few formatting related nits with it.

clang/docs/ReleaseNotes.rst

A time trace scope variable of `ParseDeclarationOrFunctionDefinition` with the function's source location is added to record the time spent parsing the function's declaration or definition. Another time trace scope variable of `ParseFunctionDefinition` is also added to record the name of the defined function. A release note is added as well. Reviewed by: Aaron Ballman Pull request: llvm#65268

A time trace scope variable of `ParseDeclarationOrFunctionDefinition` with the function's source location is added to record the time spent parsing the function's declaration or definition. Another time trace scope variable of `ParseFunctionDefinition` is also added to record the name of the defined function. A release note is added as well. Reviewed by: Aaron Ballman Pull request: #65268

MaggieYingYi · 2023-10-31T09:21:24Z

I tried to use squash and merge but the commit message using the wrong email address. Therefore, I have committed the changes using the git command.

nikic · 2023-10-31T09:50:35Z

I've reverted this change because it causes a large compile-time regression: http://llvm-compile-time-tracker.com/compare.php?from=61b9176cf70444c54f3ac6eebd82fc9ffd69944d&to=33b85867e30e1adc2ff2173039c199b81c10f52b&stat=instructions:u

From a quick glance at your implementation, I suspect the issues is that the used strings may be expensive to compute. TimeTraceScope has an overload accepting a closure that calculates the detail string for such cases.

MaggieYingYi · 2023-10-31T10:49:03Z

Hi @nikic, thanks for spotting the issue and reverted the commit.

Hi @AaronBallman,

As @nikic mentioned that the issue is that the used strings may be expensive to compute. If we remove the change to record the function name and function location, I think the issue will be fixed.

This means:

Remove the time trace scope variable of ParseFunctionDefinition.

llvm::TimeTraceScope TimeScope(
      "ParseFunctionDefinition",
      Actions.GetNameForDeclarator(D).getName().getAsString());

Remove the source location for the time trace scope variable of "ParseDeclarationOrFunctionDefinition".
Change:

  llvm::TimeTraceScope TimeScope(
      "ParseDeclarationOrFunctionDefinition",
      Tok.getLocation().printToString(
          Actions.getASTContext().getSourceManager()));

To:

  llvm::TimeTraceScope TimeScope(
      "ParseDeclarationOrFunctionDefinition");

Could you please let me know your thoughts? or any suggestion?

Thanks,
Maggie

AaronBallman · 2023-10-31T12:30:22Z

Hi @nikic, thanks for spotting the issue and reverted the commit.

Hi @AaronBallman,

As @nikic mentioned that the issue is that the used strings may be expensive to compute. If we remove the change to record the function name and function location, I think the issue will be fixed.

This means:
1. Remove the time trace scope variable of `ParseFunctionDefinition`.
llvm::TimeTraceScope TimeScope(
      "ParseFunctionDefinition",
      Actions.GetNameForDeclarator(D).getName().getAsString());
2. Remove the source location for the time trace scope variable of "ParseDeclarationOrFunctionDefinition".
   Change:
  llvm::TimeTraceScope TimeScope(
      "ParseDeclarationOrFunctionDefinition",
      Tok.getLocation().printToString(
          Actions.getASTContext().getSourceManager()));
To:
  llvm::TimeTraceScope TimeScope(
      "ParseDeclarationOrFunctionDefinition");
Could you please let me know your thoughts? or any suggestion?

Thanks, Maggie

I think the suggestion from @nikic is to use the TimeTraceScope constructor accepting a function reference instead of the one accepting a string. e.g., change to using something like:

 llvm::TimeTraceScope TimeScope(
      "ParseDeclarationOrFunctionDefinition", [&] {    
        return Tok.getLocation().printToString(
            Actions.getASTContext().getSourceManager())
         });

…tead of the one accepting a string to avoid the compile-time regression.

MaggieYingYi · 2023-10-31T20:44:48Z

Hi @AaronBallman,

Thanks so much for the explanation using an example. I now understand. I have updated the patch in the commit f66e7d2.

Kind regards,
Maggie

MaggieYingYi · 2023-11-01T12:41:02Z

Hi @AaronBallman and @nikic, are you happy for me to recommit the change? Thanks

AaronBallman

LGTM, thank you!

A time trace scope variable of `ParseDeclarationOrFunctionDefinition` with the function's source location is added to record the time spent parsing the function's declaration or definition. Another time trace scope variable of `ParseFunctionDefinition` is also added to record the name of the defined function. A release note is added as well. Reviewed by: Aaron Ballman Pull request: #65268

MaggieYingYi · 2023-11-01T13:42:30Z

Thanks @AaronBallman, the patch is recommitted.

MaggieYingYi requested review from rnk and MaskRay September 4, 2023 15:07

MaggieYingYi self-assigned this Sep 4, 2023

MaggieYingYi requested a review from a team as a code owner September 4, 2023 15:07

rnk reviewed Sep 15, 2023

View reviewed changes

MaggieYingYi requested a review from AaronBallman September 27, 2023 07:22

AaronBallman reviewed Oct 6, 2023

View reviewed changes

clang/lib/Parse/Parser.cpp Outdated Show resolved Hide resolved

MaggieYingYi force-pushed the yingyi/main/time-trace branch from a9552dc to deecf8c Compare October 12, 2023 13:28

llvmbot added clang Clang issues not falling into any other category clang:driver 'clang' and 'clang++' user-facing binaries. Not 'clang-cl' clang:frontend Language frontend issues, e.g. anything involving "Sema" labels Oct 12, 2023

AaronBallman approved these changes Oct 27, 2023

View reviewed changes

AaronBallman reviewed Oct 30, 2023

View reviewed changes

clang/docs/ReleaseNotes.rst Outdated Show resolved Hide resolved

MaggieYingYi force-pushed the yingyi/main/time-trace branch from 014ad43 to 7cd2841 Compare October 30, 2023 15:52

MaggieYingYi force-pushed the yingyi/main/time-trace branch from 7cd2841 to 8ff407f Compare October 30, 2023 20:04

MaggieYingYi force-pushed the yingyi/main/time-trace branch from 8ff407f to 5b75038 Compare October 31, 2023 07:48

MaggieYingYi closed this Oct 31, 2023

MaggieYingYi reopened this Oct 31, 2023

Use the TimeTraceScope constructor accepting a function reference ins…

f66e7d2

…tead of the one accepting a string to avoid the compile-time regression.

AaronBallman approved these changes Nov 1, 2023

View reviewed changes

MaggieYingYi closed this Nov 1, 2023

MaggieYingYi deleted the yingyi/main/time-trace branch November 7, 2023 13:35

MaggieYingYi mentioned this pull request Nov 7, 2023

-ftime-trace incorrect header hierarchy when a header contains a template function for his last symbol #56554

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[time-trace] Add a new time trace scope variable named "ParseDeclarationOrFunctionDefinition". #65268

[time-trace] Add a new time trace scope variable named "ParseDeclarationOrFunctionDefinition". #65268

MaggieYingYi commented Sep 4, 2023

MaggieYingYi commented Sep 12, 2023

rnk left a comment

MaskRay commented Sep 20, 2023

MaggieYingYi commented Sep 27, 2023

AaronBallman left a comment

llvmbot commented Oct 12, 2023 •

edited

MaggieYingYi commented Oct 27, 2023

AaronBallman left a comment

MaggieYingYi commented Oct 30, 2023

AaronBallman left a comment

MaggieYingYi commented Oct 31, 2023

nikic commented Oct 31, 2023

MaggieYingYi commented Oct 31, 2023

AaronBallman commented Oct 31, 2023

MaggieYingYi commented Oct 31, 2023

MaggieYingYi commented Nov 1, 2023

AaronBallman left a comment

MaggieYingYi commented Nov 1, 2023

[time-trace] Add a new time trace scope variable named "ParseDeclarationOrFunctionDefinition". #65268

[time-trace] Add a new time trace scope variable named "ParseDeclarationOrFunctionDefinition". #65268

Conversation

MaggieYingYi commented Sep 4, 2023

MaggieYingYi commented Sep 12, 2023

rnk left a comment

Choose a reason for hiding this comment

MaskRay commented Sep 20, 2023

MaggieYingYi commented Sep 27, 2023

AaronBallman left a comment

Choose a reason for hiding this comment

llvmbot commented Oct 12, 2023 • edited

MaggieYingYi commented Oct 27, 2023

AaronBallman left a comment

Choose a reason for hiding this comment

MaggieYingYi commented Oct 30, 2023

AaronBallman left a comment

Choose a reason for hiding this comment

MaggieYingYi commented Oct 31, 2023

nikic commented Oct 31, 2023

MaggieYingYi commented Oct 31, 2023

AaronBallman commented Oct 31, 2023

MaggieYingYi commented Oct 31, 2023

MaggieYingYi commented Nov 1, 2023

AaronBallman left a comment

Choose a reason for hiding this comment

MaggieYingYi commented Nov 1, 2023

llvmbot commented Oct 12, 2023 •

edited