Bazel client: add a simple profiler

Add a simple profiler that can measure function
call counts and durations, and report statistics
by printing to stderr.

Motivation:
I recently needed a profiler for PR bazelbuild#5445 and
PR bazelbuild#5448, so I'm adding the polished code now.

Usage:
1.  depend on //src/main/cpp/util:profiler
2.  use StopWatch, Task, and ScopedTask objects
    as shown in profiler.h's class documentation

See bazelbuild#5444

Change-Id: I43f0afd124b486c694f451e8455a66ffca8137b6

Closes bazelbuild#5461.

Change-Id: I43f0afd124b486c694f451e8455a66ffca8137b6
PiperOrigin-RevId: 202314319

src/main/cpp/util/BUILD

@@ -147,6 +147,26 @@ cc_library(
     deps = [":blaze_exit_code"],
 )
 
+cc_library(
+    name = "profiler",
+    srcs = [
+        "profiler.cc",
+    ] + select({
+        "//src/conditions:windows": ["profiler_windows.cc"],
+        "//conditions:default": ["profiler_posix.cc"],
+    }),
+    hdrs = ["profiler.h"],
+    visibility = [
+        "//src/main/cpp:__pkg__",
+        "//src/test/cpp/util:__pkg__",
+    ],
+    deps = [
+        ":blaze_exit_code",
+        ":errors",
+        ":logging",
+    ],
+)
+
 cc_library(
     name = "blaze_exit_code",
     hdrs = ["exit_code.h"],

src/main/cpp/util/profiler.cc

@@ -0,0 +1,37 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "src/main/cpp/util/profiler.h"
+
+#include <inttypes.h>
+#include <stdio.h>
+
+namespace blaze_util {
+namespace profiler {
+
+Task::~Task() {
+  Duration duration = GetDuration();
+  fprintf(stderr, "Task(%s): %" PRIu64 " calls (%" PRId64 " microseconds)\n",
+          name_, GetCalls(), duration.micros_);
+}
+
+void StopWatch::PrintAndReset(const char* name) {
+  Duration elapsed = ElapsedTime();
+  fprintf(stderr, "StopWatch(%s): %" PRId64 " microseconds elapsed\n", name,
+          elapsed.micros_);
+  Reset();
+}
+
+}  // namespace profiler
+}  // namespace blaze_util

src/main/cpp/util/profiler.h

@@ -0,0 +1,138 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#ifndef BAZEL_SRC_MAIN_CPP_UTIL_PROFILER_H_
+#define BAZEL_SRC_MAIN_CPP_UTIL_PROFILER_H_
+
+#include <stdint.h>  // int64_t
+#include <stdio.h>   // printf
+
+namespace blaze_util {
+namespace profiler {
+
+// A time duration, measured in some implementation-dependent units.
+//
+// Using a struct to wrap int64_t yields a unique type that we can't
+// accidentally use as a type-synonym of other int64_t types.
+struct Ticks {
+  int64_t value_;
+  static Ticks Now();
+};
+
+// A time duration, measured in microseconds.
+//
+// Using a struct to wrap int64_t yields a unique type that we can't
+// accidentally use as a type-synonym of other int64_t types.
+struct Duration {
+  int64_t micros_;
+  static Duration FromTicks(const Ticks ticks);
+};
+
+// Accumulates statistics about a function or some C++ scope.
+//
+// Usage: see ScopedTask.
+//
+// Records the number of times the scope was entered (the function called) and
+// the total time spent in there. Prints the statistics in the destructor.
+class Task {
+  const char* name_;
+  uint64_t calls_;
+  Ticks total_;
+
+ public:
+  Task(const char* name) : name_(name), calls_(0), total_({0}) {}
+  ~Task();
+  void AddCall() { calls_++; }
+  void AddTicks(const Ticks t) { total_.value_ += t.value_; }
+  uint64_t GetCalls() const { return calls_; }
+  Duration GetDuration() const { return Duration::FromTicks(total_); }
+};
+
+// Measures elapsed time.
+//
+// Example:
+//   void foo() {
+//     StopWatch s;
+//     ...
+//     s.PrintAndReset("marker 1");  // prints elapsed time since creation
+//     ...
+//     s.PrintAndReset("marker 2");  // prints elapsed time since "marker 1"
+//     ...
+//     s.Reset();
+//     ...
+//     Ticks t1 = s.Elapsed();  // time since Reset
+//     ...
+//     Ticks t2 = s.Elapsed();  // time since Reset, not since t1
+//   }
+//
+class StopWatch {
+  Ticks start_;
+
+ public:
+  // Constructor -- it also resets this StopWatch.
+  StopWatch() { start_ = Ticks::Now(); }
+
+  // Prints elapsed time since last reset, then resets.
+  //
+  // Args:
+  //   name: a descriptive name, will be printed in the output
+  void PrintAndReset(const char* name);
+
+  // Returns the elapsed time since the last reset as `Ticks`.
+  Ticks Elapsed() const {
+    Ticks now = Ticks::Now();
+    return {now.value_ - start_.value_};
+  }
+
+  // Returns the elapsed time since the last reset as `Duration`.
+  Duration ElapsedTime() const { return Duration::FromTicks(Elapsed()); }
+
+  // Resets this StopWatch to the current time.
+  void Reset() { start_ = Ticks::Now(); }
+};
+
+// Measures the execution duration of a given C++ scope.
+//
+// The constructor records one call of the scope in a `Task` object, and the
+// destructor records the time spent in the scope in that `Task` object.
+//
+// Usage:
+//   create one Task that accumulates the statistics for a given function
+//   or scope, and create one ScopedTask in the beginning of the scope you want
+//   to measure. Every time the scope is entered (the function is called), a
+//   ScopedTask is created, then destructed when the execution leaves the scope.
+//   The destructor then records the statistics in the Task.
+//
+// Example:
+//   Task slow_function_stats("slow function");  // d'tor prints stats
+//
+//   void slow_function() {
+//     ScopedTask prof(&slow_function_stats);
+//     ...
+//   }
+//
+class ScopedTask {
+ public:
+  ScopedTask(Task* s) : stat_(s) { stat_->AddCall(); }
+  ~ScopedTask() { stat_->AddTicks(prof_.Elapsed()); }
+
+ private:
+  Task* stat_;
+  StopWatch prof_;
+};
+
+}  // namespace profiler
+}  // namespace blaze_util
+
+#endif  // BAZEL_SRC_MAIN_CPP_UTIL_PROFILER_H_

src/main/cpp/util/profiler_posix.cc

@@ -0,0 +1,43 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "src/main/cpp/util/profiler.h"
+
+#include <time.h>
+
+#include <string>
+
+#include "src/main/cpp/util/errors.h"
+#include "src/main/cpp/util/exit_code.h"
+#include "src/main/cpp/util/logging.h"
+
+namespace blaze_util {
+namespace profiler {
+
+Ticks Ticks::Now() {
+  struct timespec ts = {};
+  if (clock_gettime(CLOCK_MONOTONIC, &ts) == -1) {
+    std::string error = GetLastErrorString();
+    BAZEL_DIE(blaze_exit_code::LOCAL_ENVIRONMENTAL_ERROR)
+        << "clock_gettime failed: " << error;
+  }
+  return {ts.tv_sec * 1000LL * 1000LL * 1000LL + ts.tv_nsec};
+}
+
+Duration Duration::FromTicks(const Ticks ticks) {
+  return {ticks.value_ / 1000LL};
+}
+
+}  // namespace profiler
+}  // namespace blaze_util

src/main/cpp/util/profiler_windows.cc

@@ -0,0 +1,49 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "src/main/cpp/util/profiler.h"
+
+#include <windows.h>
+
+#include <string>
+
+#include "src/main/cpp/util/errors.h"
+#include "src/main/cpp/util/exit_code.h"
+#include "src/main/cpp/util/logging.h"
+
+namespace blaze_util {
+namespace profiler {
+
+Ticks Ticks::Now() {
+  LARGE_INTEGER counter;
+  if (!QueryPerformanceCounter(&counter)) {
+    std::string error = GetLastErrorString();
+    BAZEL_DIE(blaze_exit_code::LOCAL_ENVIRONMENTAL_ERROR)
+        << "QueryPerformanceCounter failed: " << error;
+  }
+  return {counter.QuadPart};
+}
+
+Duration Duration::FromTicks(const Ticks t) {
+  LARGE_INTEGER freq;
+  if (!QueryPerformanceFrequency(&freq)) {
+    std::string error = GetLastErrorString();
+    BAZEL_DIE(blaze_exit_code::LOCAL_ENVIRONMENTAL_ERROR)
+        << "QueryPerformanceFrequency failed: " << error;
+  }
+  return {(t.value_ * 1000LL * 1000LL) / freq.QuadPart};
+}
+
+}  // namespace profiler
+}  // namespace blaze_util

src/test/cpp/util/BUILD

@@ -131,6 +131,15 @@ cc_test(
     }),
 )
 
+cc_test(
+    name = "profiler_test",
+    srcs = ["profiler_test.cc"],
+    deps = [
+        "//src/main/cpp/util:profiler",
+        "@com_google_googletest//:gtest_main",
+    ],
+)
+
 cc_library(
     name = "test_util",
     testonly = 1,

src/test/cpp/util/profiler_test.cc

@@ -0,0 +1,70 @@
+// Copyright 2018 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "src/main/cpp/util/profiler.h"
+
+#include <thread>  // NOLINT
+
+#include "googletest/include/gtest/gtest.h"
+
+namespace blaze_util {
+namespace profiler {
+
+static void SleepMeasurably() {
+  // The profiler should have at least 1 ms precision.
+  std::this_thread::sleep_for(std::chrono::milliseconds(1));
+}
+
+TEST(ProfilerTest, TestStopWatchMeasuresElapsedTime) {
+  StopWatch sw1, sw2;
+
+  SleepMeasurably();
+  Duration t1 = Duration::FromTicks(sw1.Elapsed());
+  SleepMeasurably();
+  Duration t2 = Duration::FromTicks(sw1.Elapsed());
+
+  // Assert that two sleeps show a longer elapsed time than one sleep.
+  ASSERT_GT(t2.micros_, t1.micros_);
+
+  sw2.Reset();
+  SleepMeasurably();
+  Duration t3_not_reset = Duration::FromTicks(sw1.Elapsed());
+  Duration t3_reset = Duration::FromTicks(sw2.Elapsed());
+
+  // Assert that sleeping the same amounts, a Reset() call results in less
+  // elapsed time in one StopWatch than in the other. (This way we don't rely on
+  // sleep completing in a timely manner.)
+  ASSERT_GT(t3_not_reset.micros_, t3_reset.micros_);
+}
+
+TEST(ProfilerTest, TestScopedTaskMeasuresElapsedTime) {
+  Task scope1("task 2"), scope2("task 2"), scope_both("tasks 1 and 2");
+  {
+    ScopedTask p1(&scope1), p2(&scope_both);
+    SleepMeasurably();
+  }
+  {
+    ScopedTask p1(&scope2), p2(&scope_both);
+    SleepMeasurably();
+    SleepMeasurably();
+  }
+  ASSERT_GT(scope2.GetDuration().micros_, scope1.GetDuration().micros_);
+  ASSERT_GT(scope_both.GetDuration().micros_, scope2.GetDuration().micros_);
+  ASSERT_EQ(scope1.GetCalls(), 1u);
+  ASSERT_EQ(scope2.GetCalls(), 1u);
+  ASSERT_EQ(scope_both.GetCalls(), 2u);
+}
+
+}  // namespace profiler
+}  // namespace blaze_util