Skip to content

Conversation

@MaskRay
Copy link
Member

@MaskRay MaskRay commented Jan 9, 2025

The code generation time is unclear in the -ftime-report output:

  • The two clang timers "Code Generation Time" and "LLVM IR Generation
    Time" are in the default group "Miscellaneous Ungrouped Timers".
  • There is also a "Clang front-end time" group, which actually includes
    code generation time.
===-------------------------------------------------------------------------===
                         Miscellaneous Ungrouped Timers
===-------------------------------------------------------------------------===

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0611 (  1.7%)   0.0099 (  4.4%)   0.0710 (  1.9%)   0.0713 (  1.9%)  LLVM IR Generation Time
   3.5140 ( 98.3%)   0.2165 ( 95.6%)   3.7306 ( 98.1%)   3.7342 ( 98.1%)  Code Generation Time
   3.5751 (100.0%)   0.2265 (100.0%)   3.8016 (100.0%)   3.8055 (100.0%)  Total
...
===-------------------------------------------------------------------------===
                          Clang front-end time report
===-------------------------------------------------------------------------===
  Total Execution Time: 3.9108 seconds (3.9146 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Clang front-end timer
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Total

This patch

  • renames "Clang front-end time report" (FrontendAction time) to "Clang
    time report",
  • renames "Clang front-end" to "Front end",
  • moves "LLVM IR Generation" into the group,
  • replaces "Code Generation time" with "Optimizer" (middle end) and
    "Machine code generation" (back end).
% clang -c sqlite3.i -w -ftime-report -mllvm -sort-timers=0
...
===-------------------------------------------------------------------------===
                               Clang time report
===-------------------------------------------------------------------------===
  Total Execution Time: 1.5922 seconds (1.5972 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.5107 ( 35.9%)   0.0105 (  6.2%)   0.5211 ( 32.7%)   0.5222 ( 32.7%)  Front end
   0.2464 ( 17.3%)   0.0340 ( 20.0%)   0.2804 ( 17.6%)   0.2814 ( 17.6%)  LLVM IR generation
   0.6240 ( 43.9%)   0.1235 ( 72.7%)   0.7475 ( 47.0%)   0.7503 ( 47.0%)  Machine code generation
   0.0413 (  2.9%)   0.0018 (  1.0%)   0.0431 (  2.7%)   0.0433 (  2.7%)  Optimizer
   1.4224 (100.0%)   0.1698 (100.0%)   1.5922 (100.0%)   1.5972 (100.0%)  Total

Created using spr 1.3.5-bogner
@llvmbot llvmbot added clang Clang issues not falling into any other category clang:codegen IR generation bugs: mangling, exceptions, etc. labels Jan 9, 2025
@llvmbot
Copy link
Member

llvmbot commented Jan 9, 2025

@llvm/pr-subscribers-llvm-support
@llvm/pr-subscribers-clang

@llvm/pr-subscribers-clang-codegen

Author: Fangrui Song (MaskRay)

Changes

Currently, the default group "Miscellaneous Ungrouped Timers" contains
"Code Generation Time" and "LLVM IR Generation Time". There is also a
"Clang front-end time report". This patch moves the two codegen timers
to "Clang front-end time report".

New output

===-------------------------------------------------------------------------===
                          Clang front-end time report
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0065 seconds (0.0066 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0001 ( 47.7%)   0.0037 ( 58.2%)   0.0038 ( 57.8%)   0.0038 ( 57.8%)  Clang front-end timer
   0.0001 ( 45.6%)   0.0024 ( 37.4%)   0.0025 ( 37.7%)   0.0025 ( 37.7%)  Code Generation Time
   0.0000 (  6.8%)   0.0003 (  4.4%)   0.0003 (  4.5%)   0.0003 (  4.5%)  LLVM IR Generation Time
   0.0002 (100.0%)   0.0063 (100.0%)   0.0065 (100.0%)   0.0066 (100.0%)  Total

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

7 Files Affected:

  • (modified) clang/include/clang/CodeGen/BackendUtil.h (+3-7)
  • (modified) clang/include/clang/Frontend/CompilerInstance.h (+4)
  • (modified) clang/lib/CodeGen/BackendConsumer.h (+2-2)
  • (modified) clang/lib/CodeGen/BackendUtil.cpp (+19-15)
  • (modified) clang/lib/CodeGen/CodeGenAction.cpp (+18-16)
  • (modified) clang/lib/CodeGen/ObjectFilePCHContainerWriter.cpp (+7-8)
  • (modified) clang/test/Frontend/ftime-report-template-decl.cpp (+6-8)
diff --git a/clang/include/clang/CodeGen/BackendUtil.h b/clang/include/clang/CodeGen/BackendUtil.h
index 7aa4f9db6c2e42..78d1e5ee8e6d59 100644
--- a/clang/include/clang/CodeGen/BackendUtil.h
+++ b/clang/include/clang/CodeGen/BackendUtil.h
@@ -25,11 +25,9 @@ class FileSystem;
 } // namespace llvm
 
 namespace clang {
+class CompilerInstance;
 class DiagnosticsEngine;
-class HeaderSearchOptions;
 class CodeGenOptions;
-class TargetOptions;
-class LangOptions;
 class BackendConsumer;
 
 enum BackendAction {
@@ -41,10 +39,8 @@ enum BackendAction {
   Backend_EmitObj       ///< Emit native object files
 };
 
-void EmitBackendOutput(DiagnosticsEngine &Diags, const HeaderSearchOptions &,
-                       const CodeGenOptions &CGOpts, const TargetOptions &TOpts,
-                       const LangOptions &LOpts, StringRef TDesc,
-                       llvm::Module *M, BackendAction Action,
+void emitBackendOutput(CompilerInstance &CI, StringRef TDesc, llvm::Module *M,
+                       BackendAction Action,
                        llvm::IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
                        std::unique_ptr<raw_pwrite_stream> OS,
                        BackendConsumer *BC = nullptr);
diff --git a/clang/include/clang/Frontend/CompilerInstance.h b/clang/include/clang/Frontend/CompilerInstance.h
index 1220a4e29471d1..3cec57abae4445 100644
--- a/clang/include/clang/Frontend/CompilerInstance.h
+++ b/clang/include/clang/Frontend/CompilerInstance.h
@@ -630,6 +630,10 @@ class CompilerInstance : public ModuleLoader {
   /// @name Frontend timer
   /// @{
 
+  llvm::TimerGroup &getFrontendTimerGroup() const {
+    return *FrontendTimerGroup;
+  }
+
   bool hasFrontendTimer() const { return (bool)FrontendTimer; }
 
   llvm::Timer &getFrontendTimer() const {
diff --git a/clang/lib/CodeGen/BackendConsumer.h b/clang/lib/CodeGen/BackendConsumer.h
index d932a78f469b95..ad3adfca367858 100644
--- a/clang/lib/CodeGen/BackendConsumer.h
+++ b/clang/lib/CodeGen/BackendConsumer.h
@@ -28,8 +28,8 @@ class BackendConsumer : public ASTConsumer {
   using LinkModule = CodeGenAction::LinkModule;
 
   virtual void anchor();
+  CompilerInstance &CI;
   DiagnosticsEngine &Diags;
-  const HeaderSearchOptions &HeaderSearchOpts;
   const CodeGenOptions &CodeGenOpts;
   const TargetOptions &TargetOpts;
   const LangOptions &LangOpts;
@@ -70,7 +70,7 @@ class BackendConsumer : public ASTConsumer {
   llvm::Module *CurLinkModule = nullptr;
 
 public:
-  BackendConsumer(const CompilerInstance &CI, BackendAction Action,
+  BackendConsumer(CompilerInstance &CI, BackendAction Action,
                   IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
                   llvm::LLVMContext &C, SmallVector<LinkModule, 4> LinkModules,
                   StringRef InFile, std::unique_ptr<raw_pwrite_stream> OS,
diff --git a/clang/lib/CodeGen/BackendUtil.cpp b/clang/lib/CodeGen/BackendUtil.cpp
index 2dbab785658aa4..bcb14a9a166077 100644
--- a/clang/lib/CodeGen/BackendUtil.cpp
+++ b/clang/lib/CodeGen/BackendUtil.cpp
@@ -137,8 +137,6 @@ class EmitAssemblyHelper {
   llvm::Module *TheModule;
   IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS;
 
-  Timer CodeGenerationTime;
-
   std::unique_ptr<raw_pwrite_stream> OS;
 
   Triple TargetTriple;
@@ -211,7 +209,6 @@ class EmitAssemblyHelper {
                      IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS)
       : Diags(_Diags), HSOpts(HeaderSearchOpts), CodeGenOpts(CGOpts),
         TargetOpts(TOpts), LangOpts(LOpts), TheModule(M), VFS(std::move(VFS)),
-        CodeGenerationTime("codegen", "Code Generation Time"),
         TargetTriple(TheModule->getTargetTriple()) {}
 
   ~EmitAssemblyHelper() {
@@ -222,8 +219,8 @@ class EmitAssemblyHelper {
   std::unique_ptr<TargetMachine> TM;
 
   // Emit output using the new pass manager for the optimization pipeline.
-  void EmitAssembly(BackendAction Action, std::unique_ptr<raw_pwrite_stream> OS,
-                    BackendConsumer *BC);
+  void emitAssembly(const CompilerInstance &CI, BackendAction Action,
+                    std::unique_ptr<raw_pwrite_stream> OS, BackendConsumer *BC);
 };
 } // namespace
 
@@ -1212,10 +1209,14 @@ void EmitAssemblyHelper::RunCodegenPipeline(
   }
 }
 
-void EmitAssemblyHelper::EmitAssembly(BackendAction Action,
+void EmitAssemblyHelper::emitAssembly(const CompilerInstance &CI,
+                                      BackendAction Action,
                                       std::unique_ptr<raw_pwrite_stream> OS,
                                       BackendConsumer *BC) {
-  TimeRegion Region(CodeGenOpts.TimePasses ? &CodeGenerationTime : nullptr);
+  Timer timer;
+  if (CodeGenOpts.TimePasses)
+    timer.init("codegen", "Code Generation Time", CI.getFrontendTimerGroup());
+  TimeRegion Region(CodeGenOpts.TimePasses ? &timer : nullptr);
   setCommandLineOpts(CodeGenOpts);
 
   bool RequiresCodeGen = actionRequiresCodeGen(Action);
@@ -1346,14 +1347,17 @@ static void runThinLTOBackend(
   }
 }
 
-void clang::EmitBackendOutput(
-    DiagnosticsEngine &Diags, const HeaderSearchOptions &HeaderOpts,
-    const CodeGenOptions &CGOpts, const clang::TargetOptions &TOpts,
-    const LangOptions &LOpts, StringRef TDesc, llvm::Module *M,
-    BackendAction Action, IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
-    std::unique_ptr<raw_pwrite_stream> OS, BackendConsumer *BC) {
-
+void clang::emitBackendOutput(CompilerInstance &CI, StringRef TDesc,
+                              llvm::Module *M, BackendAction Action,
+                              IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
+                              std::unique_ptr<raw_pwrite_stream> OS,
+                              BackendConsumer *BC) {
   llvm::TimeTraceScope TimeScope("Backend");
+  DiagnosticsEngine &Diags = CI.getDiagnostics();
+  const auto &HeaderOpts = CI.getHeaderSearchOpts();
+  const auto &CGOpts = CI.getCodeGenOpts();
+  const auto &TOpts = CI.getTargetOpts();
+  const auto &LOpts = CI.getLangOpts();
 
   std::unique_ptr<llvm::Module> EmptyModule;
   if (!CGOpts.ThinLTOIndexFile.empty()) {
@@ -1394,7 +1398,7 @@ void clang::EmitBackendOutput(
   }
 
   EmitAssemblyHelper AsmHelper(Diags, HeaderOpts, CGOpts, TOpts, LOpts, M, VFS);
-  AsmHelper.EmitAssembly(Action, std::move(OS), BC);
+  AsmHelper.emitAssembly(CI, Action, std::move(OS), BC);
 
   // Verify clang's TargetInfo DataLayout against the LLVM TargetMachine's
   // DataLayout.
diff --git a/clang/lib/CodeGen/CodeGenAction.cpp b/clang/lib/CodeGen/CodeGenAction.cpp
index f63cb9b082d5bf..8681f5f848da84 100644
--- a/clang/lib/CodeGen/CodeGenAction.cpp
+++ b/clang/lib/CodeGen/CodeGenAction.cpp
@@ -105,16 +105,17 @@ static void reportOptRecordError(Error E, DiagnosticsEngine &Diags,
       });
 }
 
-BackendConsumer::BackendConsumer(
-    const CompilerInstance &CI, BackendAction Action,
-    IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS, LLVMContext &C,
-    SmallVector<LinkModule, 4> LinkModules, StringRef InFile,
-    std::unique_ptr<raw_pwrite_stream> OS, CoverageSourceInfo *CoverageInfo,
-    llvm::Module *CurLinkModule)
-    : Diags(CI.getDiagnostics()), HeaderSearchOpts(CI.getHeaderSearchOpts()),
-      CodeGenOpts(CI.getCodeGenOpts()), TargetOpts(CI.getTargetOpts()),
-      LangOpts(CI.getLangOpts()), AsmOutStream(std::move(OS)), FS(VFS),
-      LLVMIRGeneration("irgen", "LLVM IR Generation Time"), Action(Action),
+BackendConsumer::BackendConsumer(CompilerInstance &CI, BackendAction Action,
+                                 IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
+                                 LLVMContext &C,
+                                 SmallVector<LinkModule, 4> LinkModules,
+                                 StringRef InFile,
+                                 std::unique_ptr<raw_pwrite_stream> OS,
+                                 CoverageSourceInfo *CoverageInfo,
+                                 llvm::Module *CurLinkModule)
+    : CI(CI), Diags(CI.getDiagnostics()), CodeGenOpts(CI.getCodeGenOpts()),
+      TargetOpts(CI.getTargetOpts()), LangOpts(CI.getLangOpts()),
+      AsmOutStream(std::move(OS)), FS(VFS), Action(Action),
       Gen(CreateLLVMCodeGen(Diags, InFile, std::move(VFS),
                             CI.getHeaderSearchOpts(), CI.getPreprocessorOpts(),
                             CI.getCodeGenOpts(), C, CoverageInfo)),
@@ -122,6 +123,9 @@ BackendConsumer::BackendConsumer(
   TimerIsEnabled = CodeGenOpts.TimePasses;
   llvm::TimePassesIsEnabled = CodeGenOpts.TimePasses;
   llvm::TimePassesPerRun = CodeGenOpts.TimePassesPerRun;
+  if (CodeGenOpts.TimePasses)
+    LLVMIRGeneration.init("irgen", "LLVM IR Generation Time",
+                          CI.getFrontendTimerGroup());
 }
 
 llvm::Module* BackendConsumer::getModule() const {
@@ -321,8 +325,7 @@ void BackendConsumer::HandleTranslationUnit(ASTContext &C) {
 
   EmbedBitcode(getModule(), CodeGenOpts, llvm::MemoryBufferRef());
 
-  EmitBackendOutput(Diags, HeaderSearchOpts, CodeGenOpts, TargetOpts, LangOpts,
-                    C.getTargetInfo().getDataLayoutString(), getModule(),
+  emitBackendOutput(CI, C.getTargetInfo().getDataLayoutString(), getModule(),
                     Action, FS, std::move(AsmOutStream), this);
 
   Ctx.setDiagnosticHandler(std::move(OldDiagnosticHandler));
@@ -1183,10 +1186,9 @@ void CodeGenAction::ExecuteAction() {
   std::unique_ptr<llvm::ToolOutputFile> OptRecordFile =
       std::move(*OptRecordFileOrErr);
 
-  EmitBackendOutput(
-      Diagnostics, CI.getHeaderSearchOpts(), CodeGenOpts, TargetOpts,
-      CI.getLangOpts(), CI.getTarget().getDataLayoutString(), TheModule.get(),
-      BA, CI.getFileManager().getVirtualFileSystemPtr(), std::move(OS));
+  emitBackendOutput(CI, CI.getTarget().getDataLayoutString(), TheModule.get(),
+                    BA, CI.getFileManager().getVirtualFileSystemPtr(),
+                    std::move(OS));
   if (OptRecordFile)
     OptRecordFile->keep();
 }
diff --git a/clang/lib/CodeGen/ObjectFilePCHContainerWriter.cpp b/clang/lib/CodeGen/ObjectFilePCHContainerWriter.cpp
index 71745480706ed6..5447b98d7105e0 100644
--- a/clang/lib/CodeGen/ObjectFilePCHContainerWriter.cpp
+++ b/clang/lib/CodeGen/ObjectFilePCHContainerWriter.cpp
@@ -37,6 +37,7 @@ using namespace clang;
 
 namespace {
 class PCHContainerGenerator : public ASTConsumer {
+  CompilerInstance &CI;
   DiagnosticsEngine &Diags;
   const std::string MainFileName;
   const std::string OutputFileName;
@@ -139,7 +140,7 @@ class PCHContainerGenerator : public ASTConsumer {
                         const std::string &OutputFileName,
                         std::unique_ptr<raw_pwrite_stream> OS,
                         std::shared_ptr<PCHBuffer> Buffer)
-      : Diags(CI.getDiagnostics()), MainFileName(MainFileName),
+      : CI(CI), Diags(CI.getDiagnostics()), MainFileName(MainFileName),
         OutputFileName(OutputFileName), Ctx(nullptr),
         MMap(CI.getPreprocessor().getHeaderSearchInfo().getModuleMap()),
         FS(&CI.getVirtualFileSystem()),
@@ -317,19 +318,17 @@ class PCHContainerGenerator : public ASTConsumer {
     LLVM_DEBUG({
       // Print the IR for the PCH container to the debug output.
       llvm::SmallString<0> Buffer;
-      clang::EmitBackendOutput(
-          Diags, HeaderSearchOpts, CodeGenOpts, TargetOpts, LangOpts,
-          Ctx.getTargetInfo().getDataLayoutString(), M.get(),
+      clang::emitBackendOutput(
+          CI, Ctx.getTargetInfo().getDataLayoutString(), M.get(),
           BackendAction::Backend_EmitLL, FS,
           std::make_unique<llvm::raw_svector_ostream>(Buffer));
       llvm::dbgs() << Buffer;
     });
 
     // Use the LLVM backend to emit the pch container.
-    clang::EmitBackendOutput(Diags, HeaderSearchOpts, CodeGenOpts, TargetOpts,
-                             LangOpts,
-                             Ctx.getTargetInfo().getDataLayoutString(), M.get(),
-                             BackendAction::Backend_EmitObj, FS, std::move(OS));
+    clang::emitBackendOutput(CI, Ctx.getTargetInfo().getDataLayoutString(),
+                             M.get(), BackendAction::Backend_EmitObj, FS,
+                             std::move(OS));
 
     // Free the memory for the temporary buffer.
     llvm::SmallVector<char, 0> Empty;
diff --git a/clang/test/Frontend/ftime-report-template-decl.cpp b/clang/test/Frontend/ftime-report-template-decl.cpp
index 9ba9107b980408..fa8b12c143e779 100644
--- a/clang/test/Frontend/ftime-report-template-decl.cpp
+++ b/clang/test/Frontend/ftime-report-template-decl.cpp
@@ -1,5 +1,5 @@
-// RUN: %clang_cc1 %s -emit-llvm -o - -ftime-report  2>&1 | FileCheck %s
-// RUN: %clang_cc1 %s -emit-llvm -o - -fdelayed-template-parsing -DDELAYED_TEMPLATE_PARSING -ftime-report  2>&1 | FileCheck %s
+// RUN: %clang_cc1 %s -emit-llvm -mllvm -sort-timers=0 -o - -ftime-report  2>&1 | FileCheck %s
+// RUN: %clang_cc1 %s -emit-llvm -mllvm -sort-timers=0 -o - -fdelayed-template-parsing -DDELAYED_TEMPLATE_PARSING -ftime-report  2>&1 | FileCheck %s
 
 // Template function declarations
 template <typename T>
@@ -150,10 +150,8 @@ struct _Wrap_alloc {
 };
 _Wrap_alloc<int>::rebind<int> w;
 
-// CHECK: Miscellaneous Ungrouped Timers
-// CHECK-DAG: LLVM IR Generation Time
-// CHECK-DAG: Code Generation Time
-// CHECK: Total
 // CHECK: Clang front-end time report
-// CHECK: Clang front-end timer
-// CHECK: Total
+// CHECK:      Clang front-end timer
+// CHECK-NEXT: LLVM IR Generation Time
+// CHECK-NEXT: Code Generation Time
+// CHECK-NEXT: Total

.
Created using spr 1.3.5-bogner
@MaskRay MaskRay changed the title -ftime-report: move codegen timers into FrontendTimerGroup -ftime-report: move IR generation timer into FrontendTimerGroup Jan 9, 2025
.
Created using spr 1.3.5-bogner
@MaskRay MaskRay changed the title -ftime-report: move IR generation timer into FrontendTimerGroup -ftime-report: reorganize timers Jan 9, 2025
Created using spr 1.3.5-bogner
IntrusiveRefCntPtr<llvm::vfs::FileSystem> VFS,
std::unique_ptr<raw_pwrite_stream> OS,
BackendConsumer *BC) {
llvm::TimeTraceScope TimeScope("Backend");
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I hope there is a way to unify those two timers, at least the scope of them.

timer.init("backend", "Backend", CI.getTimerGroup());
timer.startTimer();
}
auto _ = llvm::make_scope_exit([&] {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just use llvm::TimeRegion?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

emitBackendOutput is a subset of clang/lib/Frontend/FrontendAction.cpp:1074 llvm::TimeRegion Timer(CI.getFrontendTimer()). We have to start getFrontendTimer() after Backend stops (required by TimeRegion).

Since we both stop a timer and start a timer, I resort to a make_scope_exit.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it better to relocate the Frontend Timer TimeRegion instead of doing a stop and start here? I am not sure if frontend should count the time after backend (even if it isn't much time).

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is difficult.... Parsing and codegen are interleaved in clang.ParseAST calls BackendConsumer::HandleTopLevelDecl and BackendConsumer::HandleTranslationUnit (call stack, which do code generation.

I've introduced yieldTo and changed the timers. Updated the description.


Timer timer;
if (CGOpts.TimePasses) {
CI.getFrontendTimer().stopTimer();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This stopTimer() is a bit suspicious. Where is the start timer? There are assertions to make sure that start/stop is balanced. I also believe you can enter this function without ever doing frontend?

Copy link
Member Author

@MaskRay MaskRay Jan 9, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

"Clang front-end" has a TimeRegion in clang/lib/Frontend/FrontendAction.cpp.

This PR repurposes the "Clang front-end timer" (which included backend time) to remove the backend part. If we don't stop "Clang front-end" here, "Clang front-end" and "Backend" in the same group would double count the time... After this PR, "Clang front-end" is more like preprocessing, lexing, parsing, and semantic analysis.

I recalled another complaint https://aras-p.info/blog/2019/01/12/Investigating-compile-times-and-Clang-ftime-report/

“Clang front-end time report” seems to be time for “everything”, not just the frontend (Clang frontend, LLVM backend, and whatever else it did).

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see. I like the proposed time breakdown. This deserves a release note I think?

MaskRay added a commit that referenced this pull request Jan 10, 2025
@vitalybuka
Copy link
Collaborator

Probably from the prev patch I have:

/usr/local/google/home/vitalybuka/src/llvm.git/llvm-project/clang/test/Frontend/ftime-report-template-decl.cpp:155:15: error: CHECK-DAG: expected string not found in input
// CHECK-DAG: Code Generation Time
              ^
<stdin>:75:32: note: scanning from here
 Miscellaneous Ungrouped Timers
                               ^
<stdin>:79:69: note: possible intended match here
 0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) LLVM IR Generation Time
                                                                    ^

Input file: <stdin>
Check file: /usr/local/google/home/vitalybuka/src/llvm.git/llvm-project/clang/test/Frontend/ftime-report-template-decl.cpp

-dump-input=help explains the following input dump.

Input was:
<<<<<<
           .
           .
           .
          70:  0.0000 ( 1.8%) 0.0000 ( 1.8%) 0.0000 ( 2.2%) InnerAnalysisManagerProxy<FunctionAnalysisManager, Module> 
          71:  0.0000 ( 3.6%) 0.0000 ( 3.6%) 0.0000 ( 2.2%) ProfileSummaryAnalysis 
          72:  0.0001 (100.0%) 0.0001 (100.0%) 0.0001 (100.0%) Total 
          73:  
          74: ===-------------------------------------------------------------------------=== 
          75:  Miscellaneous Ungrouped Timers 
dag:155'0                                    X error: no match found
          76: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          77:  
dag:155'0     ~
          78:  ---User Time--- --System Time-- --User+System-- ---Wall Time--- --- Name --- 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          79:  0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) LLVM IR Generation Time 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
dag:155'1                                                                         ?                     possible intended match
          80:  0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) Total 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          81:  
dag:155'0     ~
          82: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          83:  Clang front-end time report 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          84: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
           .
           .
           .
>>>>>>

--

********************
^C  interrupted by user, skipping remaining tests
********************
Failed Tests (1):
  Clang :: Frontend/ftime-report-template-decl.cpp


Testing Time: 17.23s

Created using spr 1.3.5-bogner
@MaskRay
Copy link
Member Author

MaskRay commented Jan 10, 2025

Probably from the prev patch I have:

/usr/local/google/home/vitalybuka/src/llvm.git/llvm-project/clang/test/Frontend/ftime-report-template-decl.cpp:155:15: error: CHECK-DAG: expected string not found in input
// CHECK-DAG: Code Generation Time
              ^
<stdin>:75:32: note: scanning from here
 Miscellaneous Ungrouped Timers
                               ^
<stdin>:79:69: note: possible intended match here
 0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) LLVM IR Generation Time
                                                                    ^

Input file: <stdin>
Check file: /usr/local/google/home/vitalybuka/src/llvm.git/llvm-project/clang/test/Frontend/ftime-report-template-decl.cpp

-dump-input=help explains the following input dump.

Input was:
<<<<<<
           .
           .
           .
          70:  0.0000 ( 1.8%) 0.0000 ( 1.8%) 0.0000 ( 2.2%) InnerAnalysisManagerProxy<FunctionAnalysisManager, Module> 
          71:  0.0000 ( 3.6%) 0.0000 ( 3.6%) 0.0000 ( 2.2%) ProfileSummaryAnalysis 
          72:  0.0001 (100.0%) 0.0001 (100.0%) 0.0001 (100.0%) Total 
          73:  
          74: ===-------------------------------------------------------------------------=== 
          75:  Miscellaneous Ungrouped Timers 
dag:155'0                                    X error: no match found
          76: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          77:  
dag:155'0     ~
          78:  ---User Time--- --System Time-- --User+System-- ---Wall Time--- --- Name --- 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          79:  0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) LLVM IR Generation Time 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
dag:155'1                                                                         ?                     possible intended match
          80:  0.0003 (100.0%) 0.0002 (100.0%) 0.0004 (100.0%) 0.0004 (100.0%) Total 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          81:  
dag:155'0     ~
          82: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          83:  Clang front-end time report 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
          84: ===-------------------------------------------------------------------------=== 
dag:155'0     ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
           .
           .
           .
>>>>>>

--

********************
^C  interrupted by user, skipping remaining tests
********************
Failed Tests (1):
  Clang :: Frontend/ftime-report-template-decl.cpp


Testing Time: 17.23s

Sorry, my fault while simplifying some code to prepare for this PR. Should have been fixed by 186bd8e

Copy link
Collaborator

@cachemeifyoucan cachemeifyoucan left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks much better. Thanks!

Created using spr 1.3.5-bogner
@MaskRay MaskRay merged commit 0de18e7 into main Jan 11, 2025
6 of 8 checks passed
@MaskRay MaskRay deleted the users/MaskRay/spr/-ftime-report-move-codegen-timers-into-frontendtimergroup branch January 11, 2025 03:25
github-actions bot pushed a commit to arm/arm-toolchain that referenced this pull request Jan 11, 2025
The code generation time is unclear in the -ftime-report output:

* The two clang timers "Code Generation Time" and "LLVM IR Generation
  Time" are in the default group "Miscellaneous Ungrouped Timers".
* There is also a "Clang front-end time" group, which actually includes
  code generation time.

```
===-------------------------------------------------------------------------===
                         Miscellaneous Ungrouped Timers
===-------------------------------------------------------------------------===

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0611 (  1.7%)   0.0099 (  4.4%)   0.0710 (  1.9%)   0.0713 (  1.9%)  LLVM IR Generation Time
   3.5140 ( 98.3%)   0.2165 ( 95.6%)   3.7306 ( 98.1%)   3.7342 ( 98.1%)  Code Generation Time
   3.5751 (100.0%)   0.2265 (100.0%)   3.8016 (100.0%)   3.8055 (100.0%)  Total
...
===-------------------------------------------------------------------------===
                          Clang front-end time report
===-------------------------------------------------------------------------===
  Total Execution Time: 3.9108 seconds (3.9146 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Clang front-end timer
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Total
```

This patch

* renames "Clang front-end time report" (FrontendAction time) to "Clang
  time report",
* renames "Clang front-end" to "Front end",
* moves "LLVM IR Generation" into the group,
* replaces "Code Generation time" with "Optimizer" (middle end) and
  "Machine code generation" (back end).

```
% clang -c sqlite3.i -w -ftime-report -mllvm -sort-timers=0
...
===-------------------------------------------------------------------------===
                               Clang time report
===-------------------------------------------------------------------------===
  Total Execution Time: 1.5922 seconds (1.5972 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.5107 ( 35.9%)   0.0105 (  6.2%)   0.5211 ( 32.7%)   0.5222 ( 32.7%)  Front end
   0.2464 ( 17.3%)   0.0340 ( 20.0%)   0.2804 ( 17.6%)   0.2814 ( 17.6%)  LLVM IR generation
   0.6240 ( 43.9%)   0.1235 ( 72.7%)   0.7475 ( 47.0%)   0.7503 ( 47.0%)  Machine code generation
   0.0413 (  2.9%)   0.0018 (  1.0%)   0.0431 (  2.7%)   0.0433 (  2.7%)  Optimizer
   1.4224 (100.0%)   0.1698 (100.0%)   1.5922 (100.0%)   1.5972 (100.0%)  Total
```

Pull Request: llvm/llvm-project#122225
BaiXilin pushed a commit to BaiXilin/llvm-project that referenced this pull request Jan 12, 2025
BaiXilin pushed a commit to BaiXilin/llvm-project that referenced this pull request Jan 12, 2025
The code generation time is unclear in the -ftime-report output:

* The two clang timers "Code Generation Time" and "LLVM IR Generation
  Time" are in the default group "Miscellaneous Ungrouped Timers".
* There is also a "Clang front-end time" group, which actually includes
  code generation time.

```
===-------------------------------------------------------------------------===
                         Miscellaneous Ungrouped Timers
===-------------------------------------------------------------------------===

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0611 (  1.7%)   0.0099 (  4.4%)   0.0710 (  1.9%)   0.0713 (  1.9%)  LLVM IR Generation Time
   3.5140 ( 98.3%)   0.2165 ( 95.6%)   3.7306 ( 98.1%)   3.7342 ( 98.1%)  Code Generation Time
   3.5751 (100.0%)   0.2265 (100.0%)   3.8016 (100.0%)   3.8055 (100.0%)  Total
...
===-------------------------------------------------------------------------===
                          Clang front-end time report
===-------------------------------------------------------------------------===
  Total Execution Time: 3.9108 seconds (3.9146 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Clang front-end timer
   3.6802 (100.0%)   0.2306 (100.0%)   3.9108 (100.0%)   3.9146 (100.0%)  Total
```

This patch

* renames "Clang front-end time report" (FrontendAction time) to "Clang
  time report",
* renames "Clang front-end" to "Front end",
* moves "LLVM IR Generation" into the group,
* replaces "Code Generation time" with "Optimizer" (middle end) and
  "Machine code generation" (back end).

```
% clang -c sqlite3.i -w -ftime-report -mllvm -sort-timers=0
...
===-------------------------------------------------------------------------===
                               Clang time report
===-------------------------------------------------------------------------===
  Total Execution Time: 1.5922 seconds (1.5972 wall clock)

   ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.5107 ( 35.9%)   0.0105 (  6.2%)   0.5211 ( 32.7%)   0.5222 ( 32.7%)  Front end
   0.2464 ( 17.3%)   0.0340 ( 20.0%)   0.2804 ( 17.6%)   0.2814 ( 17.6%)  LLVM IR generation
   0.6240 ( 43.9%)   0.1235 ( 72.7%)   0.7475 ( 47.0%)   0.7503 ( 47.0%)  Machine code generation
   0.0413 (  2.9%)   0.0018 (  1.0%)   0.0431 (  2.7%)   0.0433 (  2.7%)  Optimizer
   1.4224 (100.0%)   0.1698 (100.0%)   1.5922 (100.0%)   1.5972 (100.0%)  Total
```

Pull Request: llvm#122225
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

clang:codegen IR generation bugs: mangling, exceptions, etc. clang Clang issues not falling into any other category llvm:support

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants