[Support][Time profiler] Make FE codegen blocks to be inside frontend blocks

[anton-afanasyev]

Summary

Add Frontend time trace entry to HandleTranslationUnit() function.
Add test to check all codegen blocks are inside frontend blocks.
Also, change --time-trace-granularity option a bit to make sure very small
time blocks are outputed to json-file when using --time-trace-granularity=0.

This fixes http://llvm.org/pr41969

[anton-afanasyev]

Small fix

[lebedev.ri]

clang/lib/CodeGen/CodeGenAction.cpp

232 ↗

(On Diff #204738)

This looks more like Frontend Codegen to me?
(With front-end itself being the entirety of clang time up to this point including this step)

[anton-afanasyev]

Updated

[anton-afanasyev]

clang/lib/CodeGen/CodeGenAction.cpp

232 ↗

(On Diff #204738)

Codegen sections are not inside HandleTranslationUnit() function only. So I've changed it other way: started Frontend section inside ParseAST() and finished this section inside HandleTranslationUnit(). Thanks!

[lebedev.ri]

clang/lib/CodeGen/CodeGenAction.cpp

250–252 ↗

(On Diff #205297)

I think i'm missing a point here.
Why do we want to end "Frontend" section here, exclude all this following diag/optremark/etc stuff?

clang/lib/Parse/ParseAST.cpp

154 ↗

(On Diff #205297)

Why not keep this as "Lexing"?

182 ↗

(On Diff #205297)

I.e. why do we not want to end it here, where the other stats are printed?

clang/test/Driver/check-time-trace-sections.py

1 ↗

(On Diff #205297)

Does some other test already require python?

[anton-afanasyev]

clang/lib/CodeGen/CodeGenAction.cpp

250–252 ↗

(On Diff #205297)

The answer is below, we have EmitBackendOutput() there, calling Backend actions.

256 ↗

(On Diff #205297)

Also the function can return here, without finishing Frontend section, if it is below.

306 ↗

(On Diff #205297)

@lebedev.ri We have EmitBackendOutput() here, calling Backend actions.

clang/lib/Parse/ParseAST.cpp

154 ↗

(On Diff #205297)

Hmm... Thanks, I'm to keep it with this name.

182 ↗

(On Diff #205297)

Cause HandleTranslationUnit() contains Backend calling.

clang/test/Driver/check-time-trace-sections.py

1 ↗

(On Diff #205297)

Sorry, what do you mean? I see many tests inside clang/test/ and llvm/test/ using python when Filecheck is not enough. Mostly they are using python -c ... as part of the pipe, but there are py-files as well.

[anton-afanasyev]

Updated

[lebedev.ri]

clang/lib/CodeGen/CodeGenAction.cpp

250–252 ↗

(On Diff #205297)

So, because we don't want "backend" timer to be within "frontend" timer.
Can you please add that as a comment here? :)

clang/test/Driver/check-time-trace-sections.py

1 ↗

(On Diff #205297)

I guess that was a dumb question, since lit is python-based.

[anton-afanasyev]

clang/lib/CodeGen/CodeGenAction.cpp

250–252 ↗

(On Diff #205297)

Ok, done.

[anton-afanasyev]

Updated

[lebedev.ri]

Hmm, i'm only now noticing how fraglie this looks.
How do we know that clang::ParseAST will only ever be called with BackendConsumer ASTConsumer?
How do we know that BackendConsumer will only ever be ASTConsumer from clang::ParseAST?

[anton-afanasyev]

In D63325#1549316, @lebedev.ri wrote:

Hmm, i'm only now noticing how fraglie this looks.
How do we know that clang::ParseAST will only ever be called with BackendConsumer ASTConsumer?
How do we know that BackendConsumer will only ever be ASTConsumer from clang::ParseAST?

This could be true by design. But I agree it's fragile. We can admit several Frontend sections though. But with this admission first variant with two Frontend TimeTraceScope's is more preferrable.

[anton-afanasyev]

clang/lib/Parse/ParseAST.cpp

167 ↗

(On Diff #205451)

@lebedev.ri This return should follow after timeTraceProfilerEnd("Frontend",...), I'm to fix it.

[anton-afanasyev]

Updated, changed test

[anton-afanasyev]

Hi @lebedev.ri, I've turned back to the solution with one TimeTraceScope for "Frontend" inside BackendConsumer::HandleTranslationUnit(), since it looks more robust. This admits several (two for now) "Frontend" sections, but I see no problem with this. Other solutions have to rely on BackendConsumer and ASTConsumer calling correct relations, which are not guaranteed (though it is looking correct for now).

[lebedev.ri]

I'm sorry, i should have noticed that earlier, the handling of "Frontend" section
still looks way too intrusive to me, it breaks abstractions.

The only simple solution i see is to

1. Insert a timer for PrettyStackTraceString CrashInfo("Per-file LLVM IR generation"); section
2. Don't stop "Frontend" timer within HandleTranslationUnit function
3. Naturally, change "Frontend" timer name to something else ("Clang invocation"?)

This is the trivial solution that wouldn't be intrusive, but would not get you the "frontend timer"
in the sense that it doesn't include the middle-end pipe, backend stuff, etc, only the

The alternative raises from the question - why does CodeGen/CodeGenAction.cpp do all that stuff?
I.e. maybe somehow chop that class into 2 or 3 smaller classes - actual ir codegen,
middle-end optimization pipeline + opt-remarks handling, etc.
I don't know if that is possible, or viable.

[lebedev.ri]

Hm, i started writing previous comment before you posted your last comment, so i didn't see the last update.
This looks less intrusive, yes, but two observations:

1. You now have two "Frontend" sections - first one being for lexing time
2. That lexing section is not within the "Frontend" section, even though it is for sure part of frontend of the compiler.

Like i said, i'm not sure what the right solution here is.

[anton-afanasyev]

In D63325#1553458, @lebedev.ri wrote:

Hm, i started writing previous comment before you posted your last comment, so i didn't see the last update.
This looks less intrusive, yes, but two observations:

1. You now have two "Frontend" sections - first one being for lexing time
2. That lexing section is not within the "Frontend" section, even though it is for sure part of frontend of the compiler.

Like i said, i'm not sure what the right solution here is.

Why lexing section is not within "Frontend" section. Your p.1 claims is is within. For now, first "Frontend" section includes lexing as well as frontend codegen (called from Consumer->HandleTopLevelDecl(). Second "Frontend" section includes only frontend codegen through HandleTranslationUnit() calling.

[anton-afanasyev]

Also, first "Frontend" section contains "ParseTemplate" and "PerformPendingInstantiations" sections.

[russell.gallop]

llvm/lib/Support/TimeProfiler.cpp

67 ↗

(On Diff #205978)

This comment looks wrong since this change. Please can you update or reword it?

[anton-afanasyev]

Changed comment

[anton-afanasyev]

llvm/lib/Support/TimeProfiler.cpp

67 ↗

(On Diff #205978)

Ok, updated.

[anton-afanasyev]

Is it ok now? I doubt that main code refactoring is a good way when adding support timer code. So ended with more robust solution, though it leads to two Frontend sections.

[anton-afanasyev]

spirit-c5ceba.json2 MBDownload

I've upload json-file and printscreen of its visualization (used https://speedscope.app). This is an example of how this patch works, making two Frontend sections.

[anton-afanasyev]

Ping!

[anton-afanasyev]

Hi all! Could it be accepted or reviewed more?

[anton-afanasyev]

Hi @lebedev.ri, could you please lgtm this or elaborate on possible issue with this?

[anton-afanasyev]

Ping!

[anton-afanasyev]

Ping!

[anton-afanasyev]

Ping!

[russell.gallop]

I don't know a lot about the structure of clang but it LGTM from the point of view of the code and traces coming out.

I'm not very keen on having two "Frontend" sections, but I think it works okay. It moves Clang CodeGen under "Frontend". "Total Frontend" and "Total Backend" between them now cover almost all of the execution time (so is more accurate than without this change).

I think there's always going to be a trade off with time-trace between presenting something simple that makes sense to an end user and revealing how LLVM/Clang is actually structured inside, which is much more complicated (and doesn't nicely fit into scopes).

[nathanchance]

This test case has never passed for me with check-clang, is there something environment related that is needed with this or are others experiencing this too?

[147/148] Running the Clang regression tests
llvm-lit: /home/nathan/cbl/git/tc-build/llvm-project/llvm/utils/lit/lit/llvm/config.py:340: note: using clang: /home/nathan/cbl/git/tc-build/build/llvm/stage1/bin/clang
FAIL: Clang :: Driver/check-time-trace-sections.cpp (4955 of 15278)
******************** TEST 'Clang :: Driver/check-time-trace-sections.cpp' FAILED ********************
Script:
--
: 'RUN: at line 2';   /home/nathan/cbl/git/tc-build/build/llvm/stage1/bin/clang --driver-mode=g++ -S -ftime-trace -ftime-trace-granularity=0 -o /home/nathan/cbl/git/tc-build/build/llvm/stage1/tools/clang/test/Driver/Output/check-time-trace-sections /home/nathan/cbl/git/tc-build/llvm-project/clang/test/Driver/check-time-trace-sections.cpp
: 'RUN: at line 3';   cat /home/nathan/cbl/git/tc-build/build/llvm/stage1/tools/clang/test/Driver/Output/check-time-trace-sections.json | "/usr/bin/python" /home/nathan/cbl/git/tc-build/llvm-project/clang/test/Driver/check-time-trace-sections.py
--
Exit Code: 1

Command Output (stderr):
--
Time trace json-file dumped to /home/nathan/cbl/git/tc-build/build/llvm/stage1/tools/clang/test/Driver/Output/check-time-trace-sections.json
Use chrome://tracing or Speedscope App (https://www.speedscope.app) for flamegraph visualization
Not all CodeGen sections are inside any Frontend section!

--

********************
Testing Time: 38.46s
********************
Failing Tests (1):
    Clang :: Driver/check-time-trace-sections.cpp

  Expected Passes    : 14008
  Expected Failures  : 15
  Unsupported Tests  : 1254
  Unexpected Failures: 1
FAILED: tools/clang/test/CMakeFiles/check-clang

This is on bdceb9fb14595d10f7d94e1dd950cf2d94d2f2d3 using this script's command: ./build-llvm.py --build-stage1-only --check-targets clang --projects clang --targets X86

[anton-afanasyev]

Hi @nathanchance , I could not reproduce your failure using the same revision and build-llvm script. Could you please attach your json report located at /home/nathan/cbl/git/tc-build/build/llvm/stage1/tools/clang/test/Driver/Output/check-time-trace-sections.json?

[nathanchance]

Done, thanks for looking into this!

check-time-trace-sections.json14 KBDownload

[anton-afanasyev]

In D63325#1643023, @nathanchance wrote:

Done, thanks for looking into this!

check-time-trace-sections.json14 KBDownload

Hmm, I still didn't manage to reproduce the issue using your json-file:

[~/llvm] > cat check-time-trace-sections.json | python llvm-project/clang/test/Driver/check-time-trace-sections.py
[~/llvm] > echo $status
0

The file itself looks good for this test: all Codegen sections are inside any Frontend section and all Frontend sections are before all Backend sections.
Also your log shows no error messages, so test should pass ok. Could it be an issue with python? What is the version you are using?

[nathanchance]

Could it be an issue with python? What is the version you are using?

I would assume so...

$ /usr/bin/python --version
Python 3.7.4

[mgehre]

I'm seeing the same issue Not all CodeGen sections are inside any Frontend section! with python 3.7.1. Json:

check-time-trace-sections.json15 KBDownload

[anton-afanasyev]

In D63325#1645892, @mgehre wrote:

I'm seeing the same issue Not all CodeGen sections are inside any Frontend section! with python 3.7.1. Json:

check-time-trace-sections.json15 KBDownload

Yes, confirmed that is python version issue, I'm working on it.

[anton-afanasyev]

Hi @nathanchance, @mgehre, fixed here: https://reviews.llvm.org/D66873, please, look at it to commit.

cfe/trunk/lib/CodeGen/CodeGenAction.cpp

 #include "llvm/IR/LLVMContext.h"
 #include "llvm/IR/Module.h"
 #include "llvm/IR/RemarkStreamer.h"
 #include "llvm/IRReader/IRReader.h"
 #include "llvm/Linker/Linker.h"
 #include "llvm/Pass.h"
 #include "llvm/Support/MemoryBuffer.h"
 #include "llvm/Support/SourceMgr.h"
+#include "llvm/Support/TimeProfiler.h"
 #include "llvm/Support/Timer.h"
 #include "llvm/Support/ToolOutputFile.h"
 #include "llvm/Support/YAMLTraits.h"
 #include "llvm/Transforms/IPO/Internalize.h"
 
 #include <memory>
 using namespace clang;
 using namespace llvm;
bool LinkInModules() {
         if (Err)
           return true;
       }
       return false; // success
     }
 
     void HandleTranslationUnit(ASTContext &C) override {
       {
+        llvm::TimeTraceScope TimeScope("Frontend", StringRef(""));
         PrettyStackTraceString CrashInfo("Per-file LLVM IR generation");
         if (FrontendTimesIsEnabled) {
           LLVMIRGenerationRefCount += 1;
           if (LLVMIRGenerationRefCount == 1)
             LLVMIRGeneration.startTimer();
         }
 
         Gen->HandleTranslationUnit(C);

cfe/trunk/test/Driver/check-time-trace-sections.cpp

+// REQUIRES: shell
+// RUN: %clangxx -S -ftime-trace -ftime-trace-granularity=0 -o %T/check-time-trace-sections %s
+// RUN: cat %T/check-time-trace-sections.json | %python %S/check-time-trace-sections.py
+
+template <typename T>
+void foo(T) {}
+void bar() { foo(0); }

cfe/trunk/test/Driver/check-time-trace-sections.py

+#!/usr/bin/env python
+
+import json, sys
+
+def is_inside(range1, range2):
+    a = range1["ts"]; b = a + range1["dur"]
+    c = range2["ts"]; d = c + range2["dur"]
+    return (a >= c and a <= d) and (b >= c and b <= d)
+
+def is_before(range1, range2):
+    b = range1["ts"] + range1["dur"]; c = range2["ts"]
+    return b <= c
+
+events = json.loads(sys.stdin.read())["traceEvents"]
+codegens = filter(lambda x: x["name"] == "CodeGen Function", events)
+frontends = filter(lambda x: x["name"] == "Frontend", events)
+backends = filter(lambda x: x["name"] == "Backend", events)
+
+if not all([any([is_inside(codegen, frontend) for frontend in frontends])
+                        for codegen in codegens]):
+    sys.exit("Not all CodeGen sections are inside any Frontend section!")
+
+if not all([all([is_before(frontend, backend) for frontend in frontends])
+                        for backend in backends]):
+    sys.exit("Not all Frontend section are before all Backend sections!")

llvm/trunk/lib/Support/TimeProfiler.cpp

Stack.emplace_back(steady_clock::now(), DurationType{}, std::move(Name),
                        Detail());
   }
 
   void end() {
     assert(!Stack.empty() && "Must call begin() first");
     auto &E = Stack.back();
     E.Duration = steady_clock::now() - E.Start;
 
-    // Only include sections longer than TimeTraceGranularity msec.
-    if (duration_cast<microseconds>(E.Duration).count() > TimeTraceGranularity)
+    // Only include sections longer or equal to TimeTraceGranularity msec.
+    if (duration_cast<microseconds>(E.Duration).count() >= TimeTraceGranularity)
       Entries.emplace_back(E);
 
     // Track total time taken by each "name", but only the topmost levels of
     // them; e.g. if there's a template instantiation that instantiates other
     // templates from within, we only want to add the topmost one. "topmost"
     // happens to be the ones that don't have any currently open entries above
     // itself.
     if (std::find_if(++Stack.rbegin(), Stack.rend(), [&](const Entry &Val) {