From c2beee142c75cf74e6aec51b3ce80a893b25995b Mon Sep 17 00:00:00 2001 From: Laszlo Csomor Date: Wed, 27 Jun 2018 08:37:12 -0700 Subject: 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 #5445 and PR #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 https://github.com/bazelbuild/bazel/issues/5444 Change-Id: I43f0afd124b486c694f451e8455a66ffca8137b6 Closes #5461. Change-Id: I43f0afd124b486c694f451e8455a66ffca8137b6 PiperOrigin-RevId: 202314319 --- src/main/cpp/util/BUILD | 20 +++++ src/main/cpp/util/profiler.cc | 37 +++++++++ src/main/cpp/util/profiler.h | 138 ++++++++++++++++++++++++++++++++++ src/main/cpp/util/profiler_posix.cc | 43 +++++++++++ src/main/cpp/util/profiler_windows.cc | 49 ++++++++++++ 5 files changed, 287 insertions(+) create mode 100644 src/main/cpp/util/profiler.cc create mode 100644 src/main/cpp/util/profiler.h create mode 100644 src/main/cpp/util/profiler_posix.cc create mode 100644 src/main/cpp/util/profiler_windows.cc (limited to 'src/main') diff --git a/src/main/cpp/util/BUILD b/src/main/cpp/util/BUILD index eed2a60a12..9df4e558d8 100644 --- a/src/main/cpp/util/BUILD +++ b/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"], diff --git a/src/main/cpp/util/profiler.cc b/src/main/cpp/util/profiler.cc new file mode 100644 index 0000000000..76c99d39d8 --- /dev/null +++ b/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 +#include + +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 diff --git a/src/main/cpp/util/profiler.h b/src/main/cpp/util/profiler.h new file mode 100644 index 0000000000..80098eef81 --- /dev/null +++ b/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 // int64_t +#include // 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_ diff --git a/src/main/cpp/util/profiler_posix.cc b/src/main/cpp/util/profiler_posix.cc new file mode 100644 index 0000000000..c86d509a2f --- /dev/null +++ b/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 + +#include + +#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 diff --git a/src/main/cpp/util/profiler_windows.cc b/src/main/cpp/util/profiler_windows.cc new file mode 100644 index 0000000000..c57a94bd6e --- /dev/null +++ b/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 + +#include + +#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 -- cgit v1.2.3