This is an archive of the discontinued LLVM Phabricator instance.

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

Authored by anton-afanasyev on Jun 14 2019, 3:38 AM.

Details

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

Event Timeline

Herald added projects: Restricted Project, Restricted Project. · View Herald TranscriptJun 14 2019, 3:38 AM
lebedev.ri added inline comments.Jun 14 2019, 4:12 PM
clang/lib/CodeGen/CodeGenAction.cpp
232

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 marked 2 inline comments as done.

Updated

clang/lib/CodeGen/CodeGenAction.cpp
232

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 added inline comments.Jun 18 2019, 2:21 PM
clang/lib/CodeGen/CodeGenAction.cpp
251–253

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 marked 10 inline comments as done.Jun 18 2019, 3:06 PM
anton-afanasyev added inline comments.
clang/lib/CodeGen/CodeGenAction.cpp
251–253

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

253

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

303

@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 marked 4 inline comments as done.

Updated

lebedev.ri marked an inline comment as done.Jun 18 2019, 3:13 PM
lebedev.ri added inline comments.
clang/lib/CodeGen/CodeGenAction.cpp
251–253

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 marked 2 inline comments as done.Jun 18 2019, 3:21 PM
anton-afanasyev added inline comments.
clang/lib/CodeGen/CodeGenAction.cpp
251–253

Ok, done.

anton-afanasyev marked an inline comment as done.

Updated

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?

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 marked an inline comment as done.Jun 18 2019, 4:13 PM
anton-afanasyev added inline comments.
clang/lib/Parse/ParseAST.cpp
167 ↗(On Diff #205451)

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

Updated, changed test

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 resigned from this revision.Jun 21 2019, 5:46 AM

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.

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.

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.

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

russell.gallop added inline comments.Jun 24 2019, 4:10 AM
llvm/lib/Support/TimeProfiler.cpp
67

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

Changed comment

anton-afanasyev marked 2 inline comments as done.Jun 24 2019, 4:24 AM
anton-afanasyev added inline comments.
llvm/lib/Support/TimeProfiler.cpp
67

Ok, updated.

anton-afanasyev marked an inline comment as done.Jun 28 2019, 12:14 AM

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.


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.

Hi all! Could it be accepted or reviewed more?

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

aras-p added a subscriber: aras-p.Jul 24 2019, 10:23 PM
russell.gallop accepted this revision.Aug 19 2019, 5:56 AM

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).

This revision is now accepted and ready to land.Aug 19 2019, 5:56 AM
This revision was automatically updated to reflect the committed changes.

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

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?

Done, thanks for looking into this!

Done, thanks for looking into this!

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?

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 added a subscriber: mgehre.Aug 26 2019, 2:09 PM

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

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

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