Add high-precision timing histograms.

components/subresource_filter/core/common/scoped_timers.h

Index: components/subresource_filter/core/common/scoped_timers.h
diff --git a/components/subresource_filter/core/common/scoped_timers.h b/components/subresource_filter/core/common/scoped_timers.h
new file mode 100644
index 0000000000000000000000000000000000000000..4be4a1b33cf22c215434a4f742b55ce442907591
--- /dev/null
+++ b/components/subresource_filter/core/common/scoped_timers.h
@@ -0,0 +1,243 @@
+// Copyright 2016 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// This file provides tools for measuring time intervals and reporting them to
+// UMA histograms or via custom functors. It is possible to measure time both
+// with base::TimeTicks and base::ThreadTicks.
+// WARNING: *UMA_HISTOGRAM_* macros in this file are not thread-safe.
+// See also: "base/metrics/histogram_macros*.h".
+//
+// TODO(pkalinnikov): Consider moving content of this file to "base/metrics/*"
+// after some refactoring. Note that most of the code generated by the macros
+// below is not thread-safe.
+
+#ifndef COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_TIMERS_
+#define COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_TIMERS_
+
+#include <type_traits>
+
+#include "base/macros.h"
+#include "base/metrics/histogram.h"
+#include "base/time/time.h"
+
+namespace subresource_filter {
+
+// Creates a scoped object that measures its lifetime using base::TimeTicks, and
+// reports the result as base::TimeDelta via provided |export_functor|. The
+// functor is copied if passed in by value.
+//
+// Example:
+//   void Function() {
+//     auto export_time = [](base::TimeDelta delta) {
+//       LOG(INFO) << "Duration: " << delta.InMicroseconds();
+//     };
+//     SCOPED_TIMER(export_time);
+//     ... Useful things happen here ...
+//   }  // |export_time| will be triggered here.
+//
+// This is recommended for when you want to measure the time it takes for a
+// method/scope to execute, including, possibly, the time spent by the thread on
+// being blocked and/or descheduled.
+#define SCOPED_TIMER(export_functor)                                  \
+  IMPL_SCOPED_TIMER_EXPANDER(impl::TimeTicksProvider, export_functor, \
+                             __COUNTER__)
+
+// Similar to SCOPED_TIMER, but uses base::ThreadTicks for measuring time.
+//
+// This is recommended for when you want to measure the time it takes for a
+// method/scope to do actual work, i.e. excluding the time spent by the thread
+// on being blocked and/or descheduled.
+#define SCOPED_THREAD_TIMER(export_functor)                             \
+  IMPL_SCOPED_TIMER_EXPANDER(impl::ThreadTicksProvider, export_functor, \
+                             __COUNTER__)
+
+// Creates a scoped object that measures its lifetime using base::ThreadTicks,
+// and reports the result in milliseconds as a UMA statistic to a histogram with
+// the provided |name| which is expected to be a runtime constant. The histogram
+// collects times up to 10 seconds in 50 buckets.
+//
+// Under the hood there is a static base::HistogramBase* pointer initialized
+// right before the scoped object. The pointer is used by a specific
+// |export_functor| passed in to a SCOPED_THREAD_TIMER (see it above).
+//
+// Example:
+//   void Function() {
+//     SCOPED_UMA_HISTOGRAM_THREAD_TIMER("Component.FunctionTime");
+//     ... Useful things happen here ...
+//   }
+//
+// WARNING: The generated code is not thread-safe.
+#define SCOPED_UMA_HISTOGRAM_THREAD_TIMER(name) \
+  IMPL_SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(     \
+      name, impl::ThreadTicksProvider,          \
+      impl::ExportTimeDeltaToHistogram<false>, 10000, __COUNTER__)
+
+// Similar to SCOPED_UMA_HISTOGRAM_THREAD_TIMER above, but the histogram
+// collects times in microseconds, up to 1 second, and using 50 buckets.
+//
+// WARNING: The generated code is not thread-safe.
+#define SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER(name)                          \
+  IMPL_SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(                                    \
+      name, impl::ThreadTicksProvider, impl::ExportTimeDeltaToHistogram<true>, \
+      1000000, __COUNTER__)
+
+// Similar to SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h",
+// but the histogram stores times in microseconds, up to 1 second, in 50
+// buckets.
+//
+// WARNING: The generated code is not thread-safe.
+#define SCOPED_UMA_HISTOGRAM_MICRO_TIMER(name)                               \
+  IMPL_SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(                                  \
+      name, impl::TimeTicksProvider, impl::ExportTimeDeltaToHistogram<true>, \

[Ilya Sherman, 2016/12/01 05:39:07]

Optional: I find it really confusing to read true vs. false here -- the labels
don't mean anything until I go read the definition below.  It would be nice to
phrase this in a way that avoids this issue.

[pkalinnikov, 2016/12/01 16:02:48]

Done.

+      1000000, __COUNTER__)

[Ilya Sherman, 2016/12/01 05:39:08]

Optional nit: I think "1000 * 1000" is easier to parse than "1000000"; ditto for
"10 * 1000" vs. "10000".

[pkalinnikov, 2016/12/01 16:02:48]

Done.

+
+// Similar to UMA_HISTOGRAM_TIMES in "base/metrics/histogram_macros.h", but
+// the histogram stores times in microseconds, up to 1 second, in 50 buckets.
+//
+// WARNING: The generated code is not thread-safe.
+#define UMA_HISTOGRAM_MICRO_TIMES(name, sample)                          \
+  UMA_HISTOGRAM_CUSTOM_MICRO_TIMES(name, sample,                         \
+                                   base::TimeDelta::FromMicroseconds(1), \
+                                   base::TimeDelta::FromSeconds(1), 50)
+
+// This can be used when the default ranges are not sufficient. This macro lets
+// the metric developer customize the min and max of the sampled range, as well
+// as the number of buckets recorded.
+#define UMA_HISTOGRAM_CUSTOM_MICRO_TIMES(name, sample, min, max, bucket_count) \
+  IMPL_UMA_HISTOGRAM_ADD(name, sample.InMicroseconds(), min.InMicroseconds(),  \
+                         max.InMicroseconds(), bucket_count)
+
+// -----------------------------------------------------------------------------
+// Below are helpers used by other macros. Shouldn't be used directly. ---------
+
+// This is necessary to expand __COUNTER__ to an actual value.
+#define IMPL_SCOPED_TIMER_EXPANDER(time_provider, export_functor, suffix) \
+  IMPL_SCOPED_TIMER_UNIQUE(time_provider, export_functor, suffix)
+
+// Creates a scoped timer, which uses |time_provider| to measure time, and
+// |export_functor| to report it.
+#define IMPL_SCOPED_TIMER_UNIQUE(time_provider, export_functor, suffix) \
+  impl::ScopedTimer<time_provider, decltype(export_functor)>            \
+      scoped_timer_##suffix(export_functor);
+
+// This is necessary to expand __COUNTER__ to an actual value.
+#define IMPL_SCOPED_UMA_HISTOGRAM_TIMER_EXPANDER(               \
+    name, time_provider, histogram_exporter, max_value, suffix) \
+  IMPL_SCOPED_UMA_HISTOGRAM_TIMER_UNIQUE(                       \
+      name, time_provider, histogram_exporter, max_value, suffix)
+
+// Creates a static histogram pointer and a scoped object referring to it
+// throught the |histogram_exporter| functor. Both the pointer and the scoped
+// object are uniquely-named, using the unique |suffix| passed in.
+#define IMPL_SCOPED_UMA_HISTOGRAM_TIMER_UNIQUE(                            \
+    name, time_provider, histogram_exporter, max_value, suffix)            \
+  IMPL_DEFINE_STATIC_UMA_HISTOGRAM_POINTER(name, 1, max_value, 50, suffix) \
+  IMPL_SCOPED_TIMER_UNIQUE(time_provider,                                  \
+                           (histogram_exporter(histogram_##suffix)), suffix)
+
+// This is necessary to expand __COUNTER__ to an actual value.
+#define IMPL_UMA_HISTOGRAM_MICRO_TIMES_EXPANDER(name, max_value, suffix, \
+                                                sample)                  \
+  IMPL_UMA_HISTOGRAM_MICRO_TIMES_UNIQUE(name, max_value, suffix, sample)
+
+// Defines a static UMA histogram pointer and writes a |sample| to it.
+#define IMPL_UMA_HISTOGRAM_ADD(name, sample, min, max, bucket_count)          \
+  do {                                                                        \
+    IMPL_DEFINE_STATIC_UMA_HISTOGRAM_POINTER(name, min, max, bucket_count, 0) \
+    histogram_0->Add(sample);                                                 \
+  } while (0)
+
+// Defines a static pointer to a UMA histogram.
+//
+// WARNING: Static local variable initialization is deliberately *not*

[engedy, 2016/11/30 12:42:28]

nit: To provide context, point to the BUILD file where this is specified.

[pkalinnikov, 2016/12/01 16:02:48]

Done.

+// thread-safe in Chrome builds.
+#define IMPL_DEFINE_STATIC_UMA_HISTOGRAM_POINTER(name, min, max, bucket_count, \
+                                                 suffix)                       \
+  static base::HistogramBase* histogram_##suffix =                             \
+      base::Histogram::FactoryGet(                                             \
+          name, min, max, bucket_count,                                        \
+          base::HistogramBase::kUmaTargetedHistogramFlag);
+
+namespace impl {
+
+// ScopedTimer is a multi-purpose scoped timer. It measures time delta from its
+// construction till destruction. For example, by putting an instance of this
+// class to the beginning of a scope it is possible to measure how long the
+// scope is being executed.
+//
+// The obtained time measurement is reported via ExportFunctor, which takes
+// base::TimeDelta as a parameter.
+//
+// Time is obtained by means of the TimeProvider static interface:
+//  * static bool IsSupported();
+//    - Idempotently returns whether the system supports such type of provider.
+//  * static void WaitUntilInitialized();
+//    - Waits until the provider can be used.
+//  * static TimeType Now();
+//    - Returns the current time of some TimeType, e.g., base::TimeTicks.
+//
+// Time measurement is exported exactly once, unless TimeProvider::IsSupported()
+// is false. In the latter case ExportFunctor is never called.
+template <typename TimeProvider, typename ExportFunctor>
+class ScopedTimer {
+ public:
+  ScopedTimer(ExportFunctor export_functor) : export_functor_(export_functor) {
+    if (TimeProvider::IsSupported()) {
+      TimeProvider::WaitUntilInitialized();
+      construction_time_ = TimeProvider::Now();
+    }
+  }
+
+  ~ScopedTimer() {
+    if (TimeProvider::IsSupported()) {
+      const base::TimeDelta delta = TimeProvider::Now() - construction_time_;
+      export_functor_(delta);
+    }
+  }
+
+ private:
+  using TimeType =
+      typename std::remove_reference<decltype(TimeProvider::Now())>::type;
+
+  ExportFunctor export_functor_;
+  TimeType construction_time_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedTimer);
+};
+
+// TimeProvider implementations ------------------------------------------------
+
+class TimeTicksProvider {
+ public:
+  static bool IsSupported() { return true; }
+  static void WaitUntilInitialized() {}
+  static base::TimeTicks Now() { return base::TimeTicks::Now(); }
+};
+
+using ThreadTicksProvider = base::ThreadTicks;
+
+// ExportFunctor implementations -----------------------------------------------
+
+template <bool is_microsec_precision>
+class ExportTimeDeltaToHistogram {
+ public:
+  ExportTimeDeltaToHistogram(base::HistogramBase* histogram)
+      : histogram_(histogram) {}
+
+  void operator()(base::TimeDelta delta) {
+    if (is_microsec_precision)
+      histogram_->Add(delta.InMicroseconds());
+    else
+      histogram_->Add(delta.InMilliseconds());
+  }
+
+ private:
+  base::HistogramBase* histogram_;
+};
+
+}  // namespace impl
+
+}  // namespace subresource_filter
+
+#endif  // COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_TIMERS_