[PATCH] D47196: [Time-report ](2): Recursive timers in Clang

Tue Jul 10 07:21:41 PDT 2018

avt77 added a comment.

In https://reviews.llvm.org/D47196#1134185, @efriedma wrote:

> Can you give an example of what the output looks like?

First of all excuse me for such delay with my answer: I was on my vacations.
During bootstrap we could see something like here:

[ 84%] Building CXX object tools/clang/lib/StaticAnalyzer/Core/CMakeFiles/clangStaticAnalyzerCore.dir/BlockCounter.cpp.o

------------ Clang Timers: CodeGen Functions ------------
---------------------------------------------------------

0.0080 (2) _ZN5clang7tooling20getOccurrencesOfUSRsEN4llvm8ArrayRefINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENS1_9StringRefEPNS_4DeclE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE12TraverseAttrEPNS_4AttrE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE29TraverseOMPTaskyieldDirectiveEPNS_21OMPTaskyieldDirectiveEPN4llvm15SmallVectorImplINS7_14PointerIntPairIPNS_4StmtELj1EbNS7_21PointerLikeTypeTraitsISB_EENS7_18PointerIntPairInfoISB_Lj1ESD_EEEEEE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE16TraverseBinCommaEPNS_14BinaryOperatorEPN4llvm15SmallVectorImplINS9_14PointerIntPairIPNS_4StmtELj1EbNS9_21PointerLikeTypeTraitsISD_EENS9_18PointerIntPairInfoISD_Lj1ESF_EEEEEE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE21TraverseTypeAliasDeclEPNS_13TypeAliasDeclE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE22TraverseObjCObjectTypeEPNS_14ObjCObjectTypeE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE12TraverseDeclEPNS_4DeclE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE37TraverseVarTemplateSpecializationDeclEPNS_29VarTemplateSpecializationDeclE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE13TraverseBinGTEPNS_14BinaryOperatorEPN4llvm15SmallVectorImplINS7_14PointerIntPairIPNS_4StmtELj1EbNS7_21PointerLikeTypeTraitsISB_EENS7_18PointerIntPairInfoISB_Lj1ESD_EEEEEE (*)
 0.0080 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE31TraverseCXXPseudoDestructorExprEPNS_23CXXPseudoDestructorExprEPN4llvm15SmallVectorImplINS7_14PointerIntPairIPNS_4StmtELj1EbNS7_21PointerLikeTypeTraitsISB_EENS7_18PointerIntPairInfoISB_Lj1ESD_EEEEEE (*)
 0.0120 (2) _ZN5clang7tooling25createRenameAtomicChangesEN4llvm8ArrayRefINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENS1_9StringRefEPNS_4DeclE (*)
 0.0120 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE15TraverseTypeLocENS_7TypeLocE (*)
 0.0160 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE13PostVisitStmtEPNS_4StmtE (*)
 0.0200 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE12TraverseAttrEPNS_4AttrE (*)
 0.0200 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE13PostVisitStmtEPNS_4StmtE (*)
 0.0400 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling12_GLOBAL__N_115RenameLocFinderEE16dataTraverseNodeEPNS_4StmtEPN4llvm15SmallVectorImplINS7_14PointerIntPairIS6_Lj1EbNS7_21PointerLikeTypeTraitsIS6_EENS7_18PointerIntPairInfoIS6_Lj1ESB_EEEEEE (*)
 0.0440 (2) _ZN5clang19RecursiveASTVisitorINS_7tooling22RecursiveSymbolVisitorINS1_12_GLOBAL__N_123USRLocFindingASTVisitorEEEE16dataTraverseNodeEPNS_4StmtEPN4llvm15SmallVectorImplINS9_14PointerIntPairIS8_Lj1EbNS9_21PointerLikeTypeTraitsIS8_EENS9_18PointerIntPairInfoIS8_Lj1ESD_EEEEEE (*)
 0.0720 (1) _ZN5clang19RecursiveASTVisitor12TraverseAttrEPNS_4AttrE (*)

If we collect the full build log, grep and sort it then we could see the longest compilation times like here:

0.3240 (2) _ZN4llvm18HexagonInstPrinter16printInstructionEPKNS_6MCInstERNS_11raw_ostreamE (*)
 0.4520 (2) _ZNK4llvm19AMDGPUMCCodeEmitter27verifyInstructionPredicatesERKNS_6MCInstEm (*)
 0.4680 (2) _ZN12_GLOBAL__N_119SystemZDAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)
 0.5960 (2) _ZL20validateOperandClassRN4llvm18MCParsedAsmOperandEN12_GLOBAL__N_114MatchClassKindE (*)
 0.6200 (2) _ZN12_GLOBAL__N_115ARMDAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)
 0.7280 (2) _ZN12_GLOBAL__N_115PPCDAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)
 0.7920 (2) _ZN12_GLOBAL__N_119AArch64DAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)
 1.3160 (3) _ZN4llvm19HexagonDAGToDAGISel10SelectCodeEPNS_6SDNodeE (*)
 1.4760 (2) _ZN12_GLOBAL__N_118AMDGPUDAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)
 5.2520 (2) _ZN12_GLOBAL__N_115X86DAGToDAGISel10SelectCodeEPN4llvm6SDNodeE (*)

> It seems like you've scattered the "start" and "stop" calls all over the place; can you put the start and stop calls in the same place, somehow?

I use now startFrontendTimer/stopFronendTimer: you can find it in several files and inside RAII objects.

https://reviews.llvm.org/D47196