[clang] [clang][deps] Improve timing output (PR #113726)

[Jan Svoboda via cfe-commits]

https://github.com/jansvoboda11 updated https://github.com/llvm/llvm-project/pull/113726

>From 58056a40734ee2a64dca37f7669f77f2447f492c Mon Sep 17 00:00:00 2001
From: Jan Svoboda <jan_svoboda at apple.com>
Date: Fri, 25 Oct 2024 11:42:58 -0700
Subject: [PATCH 1/2] [clang][deps] Improve timing output

This patch adds the number of executed instructions into the timing output, which provides more stable results compared to wall or process time.

The format itself is also tweaked so that it's more amenable for direct import into a spreadsheet editor. The new `-no-print-timing-header` flag can be used so that only the first out of multiple runs prints the header annotating the data.
---
 clang/tools/clang-scan-deps/ClangScanDeps.cpp | 16 ++++++++++++----
 clang/tools/clang-scan-deps/Opts.td           |  1 +
 2 files changed, 13 insertions(+), 4 deletions(-)

diff --git a/clang/tools/clang-scan-deps/ClangScanDeps.cpp b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
index 7d36cee7a22b39..f6d121d86c22d8 100644
--- a/clang/tools/clang-scan-deps/ClangScanDeps.cpp
+++ b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
@@ -88,6 +88,7 @@ static bool DeprecatedDriverCommand;
 static ResourceDirRecipeKind ResourceDirRecipe;
 static bool Verbose;
 static bool PrintTiming;
+static bool NoPrintTimingHeader;
 static llvm::BumpPtrAllocator Alloc;
 static llvm::StringSaver Saver{Alloc};
 static std::vector<const char *> CommandLine;
@@ -220,6 +221,7 @@ static void ParseArgs(int argc, char **argv) {
   }
 
   PrintTiming = Args.hasArg(OPT_print_timing);
+  NoPrintTimingHeader = Args.hasArg(OPT_no_print_timing_header);
 
   Verbose = Args.hasArg(OPT_verbose);
 
@@ -1080,10 +1082,16 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
                  << NumExistsCalls << " exists() calls\n"
                  << NumIsLocalCalls << " isLocal() calls\n";
 
-  if (PrintTiming)
-    llvm::errs() << llvm::format(
-        "clang-scan-deps timing: %0.2fs wall, %0.2fs process\n",
-        T.getTotalTime().getWallTime(), T.getTotalTime().getProcessTime());
+  if (PrintTiming) {
+    if (!NoPrintTimingHeader)
+      llvm::errs() << "wall time [s]\t"
+                   << "process time [s]\t"
+                   << "instruction count\n";
+    const llvm::TimeRecord &R = T.getTotalTime();
+    llvm::errs() << llvm::format("%0.4f", R.getWallTime()) << "\t"
+                 << llvm::format("%0.4f", R.getProcessTime()) << "\t"
+                 << llvm::format("%llu", R.getInstructionsExecuted()) << "\n";
+  }
 
   if (RoundTripArgs)
     if (FD && FD->roundTripCommands(llvm::errs()))
diff --git a/clang/tools/clang-scan-deps/Opts.td b/clang/tools/clang-scan-deps/Opts.td
index 4837ce6f070d73..2ddcdf5f90fec9 100644
--- a/clang/tools/clang-scan-deps/Opts.td
+++ b/clang/tools/clang-scan-deps/Opts.td
@@ -34,6 +34,7 @@ def deprecated_driver_command : F<"deprecated-driver-command", "use a single dri
 defm resource_dir_recipe : Eq<"resource-dir-recipe", "How to produce missing '-resource-dir' argument">;
 
 def print_timing : F<"print-timing", "Print timing information">;
+def no_print_timing_header : F<"no-print-timing-header", "Do not print the timing information header">;
 
 def verbose : F<"v", "Use verbose output">;
 

>From ce58922c1b00a38cca4da75ecf4e756ceca2199d Mon Sep 17 00:00:00 2001
From: Jan Svoboda <jan_svoboda at apple.com>
Date: Mon, 28 Oct 2024 12:16:33 -0700
Subject: [PATCH 2/2] Remove new flag, adjust test

---
 clang/test/ClangScanDeps/print-timing.c       | 3 ++-
 clang/tools/clang-scan-deps/ClangScanDeps.cpp | 9 +++------
 clang/tools/clang-scan-deps/Opts.td           | 1 -
 3 files changed, 5 insertions(+), 8 deletions(-)

diff --git a/clang/test/ClangScanDeps/print-timing.c b/clang/test/ClangScanDeps/print-timing.c
index f27df1ebf732a9..fa2a433b955370 100644
--- a/clang/test/ClangScanDeps/print-timing.c
+++ b/clang/test/ClangScanDeps/print-timing.c
@@ -3,7 +3,8 @@
 
 // RUN: clang-scan-deps -compilation-database %t/cdb.json -print-timing > %t/result.json 2>%t/errs
 // RUN: cat %t/errs | FileCheck %s
-// CHECK: clang-scan-deps timing: {{[0-9]+}}.{{[0-9][0-9]}}s wall, {{[0-9]+}}.{{[0-9][0-9]}}s process
+// CHECK:      wall time [s]              process time [s]           instruction count
+// CHECK-NEXT: {{[0-9]+}}.{{([0-9]{4})}}  {{[0-9]+}}.{{([0-9]{4})}}  {{[0-9]+}}
 
 //--- cdb.json
 []
diff --git a/clang/tools/clang-scan-deps/ClangScanDeps.cpp b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
index f6d121d86c22d8..f474b1346b1be1 100644
--- a/clang/tools/clang-scan-deps/ClangScanDeps.cpp
+++ b/clang/tools/clang-scan-deps/ClangScanDeps.cpp
@@ -88,7 +88,6 @@ static bool DeprecatedDriverCommand;
 static ResourceDirRecipeKind ResourceDirRecipe;
 static bool Verbose;
 static bool PrintTiming;
-static bool NoPrintTimingHeader;
 static llvm::BumpPtrAllocator Alloc;
 static llvm::StringSaver Saver{Alloc};
 static std::vector<const char *> CommandLine;
@@ -221,7 +220,6 @@ static void ParseArgs(int argc, char **argv) {
   }
 
   PrintTiming = Args.hasArg(OPT_print_timing);
-  NoPrintTimingHeader = Args.hasArg(OPT_no_print_timing_header);
 
   Verbose = Args.hasArg(OPT_verbose);
 
@@ -1083,10 +1081,9 @@ int clang_scan_deps_main(int argc, char **argv, const llvm::ToolContext &) {
                  << NumIsLocalCalls << " isLocal() calls\n";
 
   if (PrintTiming) {
-    if (!NoPrintTimingHeader)
-      llvm::errs() << "wall time [s]\t"
-                   << "process time [s]\t"
-                   << "instruction count\n";
+    llvm::errs() << "wall time [s]\t"
+                 << "process time [s]\t"
+                 << "instruction count\n";
     const llvm::TimeRecord &R = T.getTotalTime();
     llvm::errs() << llvm::format("%0.4f", R.getWallTime()) << "\t"
                  << llvm::format("%0.4f", R.getProcessTime()) << "\t"
diff --git a/clang/tools/clang-scan-deps/Opts.td b/clang/tools/clang-scan-deps/Opts.td
index 2ddcdf5f90fec9..4837ce6f070d73 100644
--- a/clang/tools/clang-scan-deps/Opts.td
+++ b/clang/tools/clang-scan-deps/Opts.td
@@ -34,7 +34,6 @@ def deprecated_driver_command : F<"deprecated-driver-command", "use a single dri
 defm resource_dir_recipe : Eq<"resource-dir-recipe", "How to produce missing '-resource-dir' argument">;
 
 def print_timing : F<"print-timing", "Print timing information">;
-def no_print_timing_header : F<"no-print-timing-header", "Do not print the timing information header">;
 
 def verbose : F<"v", "Use verbose output">;