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..2c1aa92d9b8bb0a5276783318ff58d2651c3d68c
--- /dev/null
+++ b/components/subresource_filter/core/common/scoped_timers.h
@@ -0,0 +1,232 @@
+// 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.

[Ilya Sherman, 2016/11/29 03:02:48]

Please explicitly mention the lack of thread-safety

[pkalinnikov, 2016/11/30 10:13:47]

Done.

+//
+// See also: "base/metrics/histogram_macros*.h".
+//
+// TODO(pkalinnikov): Content of this file should probably be considered to move
+// to "histogram_macros.h" and "histogram_macros_impl.h" at "base/metrics/"
+// after some refactoring.

[Ilya Sherman, 2016/11/29 03:02:48]

Please explicitly mention the lack of thread-safety in this TODO (yes, in
addition to mentioning it above -- it's important to mention it above for any
users of this file, and it's important to mention here for anyone thinking about
doing the refactoring).

[pkalinnikov, 2016/11/30 10:13:48]

Done.

+
+#ifndef COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_UMA_HISTOGRAM_TIMERS_
+#define COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_UMA_HISTOGRAM_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|.
+//
+// Example:
+//   void Function() {
+//     auto export_time = [](base::TimeDelta delta) {
+//       LOG(INFO) << "Duration: " << delta.InMicroseconds();
+//     };
+//     SCOPED_TIMER(export_time);

[Ilya Sherman, 2016/11/29 03:02:48]

Does this actually need to be a macro?  If so, why?

[pkalinnikov, 2016/11/30 10:13:47]

Two reasons:
1. To have the same style as other SCOPED_* macros.
2. To be less wordy. Compare:
   - SCOPED_TIMER(functor); vs. ScopedTimer<FunctorType> scoped_timer(functor);
   - SCOPED_TIMER(stored_lambda); vs. ScopedTimer<decltype(stored_lambda)>
scoped_timer(stored_lambda);

Otherwise, I don't have stronger arguments towards macro. What do you think?

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

Could you define a ScopedTimer class that runs a base::Callback that accepts a
TimeDelta?  (Or maybe there's an equivalent way to phrase that with lambda
functions?  Basically, I'm not sure why a template would need to be involved.)

+//     ... 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 ...
+//   }
+//
+// WARN: The generated code is not thread-safe.

[Ilya Sherman, 2016/11/29 03:02:48]

nit: s/WARN/WARNING or NOTE or CAUTION

[pkalinnikov, 2016/11/30 10:13:47]

Done.

+#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 100 milliseconds, and using 50 buckets.
+//
+// WARN: 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>, \
+      100000, __COUNTER__)
+
+// Similar to SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h",
+// but the histogram stores times in microseconds, up to 100 milliseconds, in 50
+// buckets.
+//
+// WARN: 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>, \
+      100000, __COUNTER__)
+
+// Similar to UMA_HISTOGRAM_TIMES in "base/metrics/histogram_macros.h", but
+// the histogram stores times in microseconds, up to 100 milliseconds, in 50
+// buckets.
+//
+// WARN: The generated code is not thread-safe.
+#define UMA_HISTOGRAM_MICRO_TIMES(name, sample)                      \
+  IMPL_UMA_HISTOGRAM_MICRO_TIMES_EXPANDER(name, 100000, __COUNTER__, \
+                                          sample.InMicroseconds())
+
+// -----------------------------------------------------------------------------
+// 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_histogram_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, max_value, 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_MICRO_TIMES_UNIQUE(name, max_value, suffix, sample) \
+  IMPL_DEFINE_STATIC_UMA_HISTOGRAM_POINTER(name, max_value, suffix)            \
+  histogram_##suffix->Add(sample);
+
+// Defines a static pointer to a UMA histogram.
+//
+// WARN: Static local variable initialization is deliberately *not* thread-safe
+// in Chrome builds.
+#define IMPL_DEFINE_STATIC_UMA_HISTOGRAM_POINTER(name, max_value, suffix) \
+  static base::HistogramBase* histogram_##suffix =                        \
+      base::Histogram::FactoryGet(                                        \
+          name, 1, max_value, 50,                                         \
+          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_UMA_HISTOGRAM_TIMERS_