[Timer] On macOS count number of executed instructions

In addition to wall time etc. this should allow us to get less noisy
values for time measurements.

Author: ahoppen

clang-tools-extra/test/clang-tidy/infrastructure/clang-tidy-store-check-profile-one-tu.cpp

@@ -17,8 +17,9 @@
 // CHECK-FILE-NEXT:"profile": {
 // CHECK-FILE-NEXT:	"time.clang-tidy.readability-function-size.wall": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}},
 // CHECK-FILE-NEXT:	"time.clang-tidy.readability-function-size.user": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}},
-// CHECK-FILE-NEXT:	"time.clang-tidy.readability-function-size.sys": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}}
-// CHECK-FILE-NEXT: }
+// CHECK-FILE-NEXT:	"time.clang-tidy.readability-function-size.sys": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}}{{,?}}
+// If available on the platform, we also have a "time.clang-tidy.readability-function-size.instr" entry
+// CHECK-FILE: }
 // CHECK-FILE-NEXT: }
 
 // CHECK-FILE-NOT: {
@@ -27,7 +28,7 @@
 // CHECK-FILE-NOT: "profile": {
 // CHECK-FILE-NOT:	"time.clang-tidy.readability-function-size.wall": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}},
 // CHECK-FILE-NOT:	"time.clang-tidy.readability-function-size.user": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}},
-// CHECK-FILE-NOT:	"time.clang-tidy.readability-function-size.sys": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}}
+// CHECK-FILE-NOT:	"time.clang-tidy.readability-function-size.sys": {{.*}}{{[0-9]}}.{{[0-9]+}}e{{[-+]}}{{[0-9]}}{{[0-9]}}{{,?}}
 // CHECK-FILE-NOT: }
 // CHECK-FILE-NOT: }
 

llvm/CMakeLists.txt

@@ -703,6 +703,12 @@ else()
 endif()
 option(LLVM_ENABLE_PLUGINS "Enable plugin support" ${LLVM_ENABLE_PLUGINS_default})
 
+include(CheckSymbolExists)
+ check_symbol_exists(proc_pid_rusage "libproc.h" HAVE_PROC_PID_RUSAGE)
+ if(HAVE_PROC_PID_RUSAGE)
+   list(APPEND CMAKE_REQUIRED_LIBRARIES proc)
+ endif()
+
 set(ENABLE_EXPERIMENTAL_NEW_PASS_MANAGER FALSE CACHE BOOL
   "Enable the experimental new pass manager by default.")
 

llvm/include/llvm/Config/config.h.cmake

@@ -350,4 +350,6 @@
 /* Whether Timers signpost passes in Xcode Instruments */
 #cmakedefine01 LLVM_SUPPORT_XCODE_SIGNPOSTS
 
+#cmakedefine HAVE_PROC_PID_RUSAGE 1
+
 #endif

llvm/include/llvm/Support/Timer.h

@@ -24,12 +24,14 @@ class TimerGroup;
 class raw_ostream;
 
 class TimeRecord {
-  double WallTime;       ///< Wall clock time elapsed in seconds.
-  double UserTime;       ///< User time elapsed.
-  double SystemTime;     ///< System time elapsed.
-  ssize_t MemUsed;       ///< Memory allocated (in bytes).
+  double WallTime;                ///< Wall clock time elapsed in seconds.
+  double UserTime;                ///< User time elapsed.
+  double SystemTime;              ///< System time elapsed.
+  ssize_t MemUsed;                ///< Memory allocated (in bytes).
+  uint64_t InstructionsExecuted;  ///< Number of instructions executed
 public:
-  TimeRecord() : WallTime(0), UserTime(0), SystemTime(0), MemUsed(0) {}
+  TimeRecord() : WallTime(0), UserTime(0), SystemTime(0), MemUsed(0),
+                 InstructionsExecuted(0) {}
 
   /// Get the current time and memory usage.  If Start is true we get the memory
   /// usage before the time, otherwise we get time before memory usage.  This
@@ -42,23 +44,26 @@ class TimeRecord {
   double getSystemTime() const { return SystemTime; }
   double getWallTime() const { return WallTime; }
   ssize_t getMemUsed() const { return MemUsed; }
+  uint64_t getInstructionsExecuted() const { return InstructionsExecuted; }
 
   bool operator<(const TimeRecord &T) const {
     // Sort by Wall Time elapsed, as it is the only thing really accurate
     return WallTime < T.WallTime;
   }
 
   void operator+=(const TimeRecord &RHS) {
-    WallTime   += RHS.WallTime;
-    UserTime   += RHS.UserTime;
-    SystemTime += RHS.SystemTime;
-    MemUsed    += RHS.MemUsed;
+    WallTime             += RHS.WallTime;
+    UserTime             += RHS.UserTime;
+    SystemTime           += RHS.SystemTime;
+    MemUsed              += RHS.MemUsed;
+    InstructionsExecuted += RHS.InstructionsExecuted;
   }
   void operator-=(const TimeRecord &RHS) {
-    WallTime   -= RHS.WallTime;
-    UserTime   -= RHS.UserTime;
-    SystemTime -= RHS.SystemTime;
-    MemUsed    -= RHS.MemUsed;
+    WallTime             -= RHS.WallTime;
+    UserTime             -= RHS.UserTime;
+    SystemTime           -= RHS.SystemTime;
+    MemUsed              -= RHS.MemUsed;
+    InstructionsExecuted -= RHS.InstructionsExecuted;
   }
 
   /// Print the current time record to \p OS, with a breakdown showing

llvm/lib/Support/Timer.cpp

@@ -13,6 +13,7 @@
 #include "llvm/Support/Timer.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringMap.h"
+#include "llvm/Config/config.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/FileSystem.h"
 #include "llvm/Support/Format.h"
@@ -24,6 +25,14 @@
 #include "llvm/Support/raw_ostream.h"
 #include <limits>
 
+#if HAVE_UNISTD_H
+#include <unistd.h>
+#endif
+
+#ifdef HAVE_PROC_PID_RUSAGE
+#include <libproc.h>
+#endif
+
 using namespace llvm;
 
 // This ugly hack is brought to you courtesy of constructor/destructor ordering
@@ -120,6 +129,16 @@ static inline size_t getMemUsage() {
   return sys::Process::GetMallocUsage();
 }
 
+static uint64_t getCurInstructionsExecuted() {
+#if defined(HAVE_UNISTD_H) && defined(HAVE_PROC_PID_RUSAGE) && defined(RUSAGE_INFO_V4)
+  struct rusage_info_v4 ru;
+  if (proc_pid_rusage(getpid(), RUSAGE_INFO_V4, (rusage_info_t *)&ru) == 0) {
+    return ru.ri_instructions;
+  }
+#endif
+  return 0;
+}
+
 TimeRecord TimeRecord::getCurrentTime(bool Start) {
   using Seconds = std::chrono::duration<double, std::ratio<1>>;
   TimeRecord Result;
@@ -128,9 +147,11 @@ TimeRecord TimeRecord::getCurrentTime(bool Start) {
 
   if (Start) {
     Result.MemUsed = getMemUsage();
+    Result.InstructionsExecuted = getCurInstructionsExecuted();
     sys::Process::GetTimeUsage(now, user, sys);
   } else {
     sys::Process::GetTimeUsage(now, user, sys);
+    Result.InstructionsExecuted = getCurInstructionsExecuted();
     Result.MemUsed = getMemUsage();
   }
 
@@ -180,6 +201,8 @@ void TimeRecord::print(const TimeRecord &Total, raw_ostream &OS) const {
 
   if (Total.getMemUsed())
     OS << format("%9" PRId64 "  ", (int64_t)getMemUsed());
+  if (Total.getInstructionsExecuted())
+    OS << format("%9" PRId64 "  ", (int64_t)getInstructionsExecuted());
 }
 
 
@@ -339,6 +362,8 @@ void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
   OS << "   ---Wall Time---";
   if (Total.getMemUsed())
     OS << "  ---Mem---";
+  if (Total.getInstructionsExecuted())
+    OS << "  ---Instr---";
   OS << "  --- Name ---\n";
 
   // Loop through all of the timing data, printing it out.
@@ -433,6 +458,10 @@ const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
       OS << delim;
       printJSONValue(OS, R, ".mem", T.getMemUsed());
     }
+    if (T.getInstructionsExecuted()) {
+      OS << delim;
+      printJSONValue(OS, R, ".instr", T.getInstructionsExecuted());
+    }
   }
   TimersToPrint.clear();
   return delim;