Add high-precision timing histograms.

components/subresource_filter/core/common/scoped_uma_histogram_timers.h

Index: components/subresource_filter/core/common/scoped_uma_histogram_timers.h
diff --git a/components/subresource_filter/core/common/scoped_uma_histogram_timers.h b/components/subresource_filter/core/common/scoped_uma_histogram_timers.h
new file mode 100644
index 0000000000000000000000000000000000000000..2bb3162e4ab02144952cf98c78efa6b8f461e9ea
--- /dev/null
+++ b/components/subresource_filter/core/common/scoped_uma_histogram_timers.h
@@ -0,0 +1,112 @@
+// Copyright 2016 The Chromium Authors. All rights reserved.

[engedy, 2016/11/16 14:48:07]

Could you please run this entire file by rkaplow@ and get his thoughts on it?

[pkalinnikov, 2016/11/17 15:24:31]

Will add him as a reviewer.

+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+// This file provides macros for reporting TimeTicks/ThreadTicks with

[engedy, 2016/11/16 14:48:07]

nit: s/reporting/recording

[pkalinnikov, 2016/11/17 15:24:32]

Done.

+// milli/microsecond precision to UMA histograms.
+//
+// TODO(pkalinnikov): Content of this file should probably be considered to move
+// to "histogram_macros.h" and "histogram_macros_internal.h" at "base/metrics/"
+// after some refactoring.
+

[pkalinnikov, 2016/11/16 13:53:48]

Add include guards.

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+#include "base/metrics/histogram.h"
+#include "base/time/time.h"
+
+namespace subresource_filter {
+
+// Scoped class which logs its time on this thread, measured in milliseconds, as

[engedy, 2016/11/16 14:48:07]

How about:

... which records how long the current thread has been doing actual work during
the lifetime of the instance, measured ...

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+// a UMA statistic.
+//
+// This is recommended for when you want a histogram which measures the time it
+// takes for a method to execute, taking into account only the time when the
+// thread had been doing actual work. This measures up to 10 seconds. It uses
+// base::HistogramBase::Add directly under the hood.
+//
+// Each macro call site results in a static base::HistogramBase* uniquely-named
+// pointer created, followed by a RAII object referring to that histogram, and

[engedy, 2016/11/16 14:48:07]

nit: What is the resource that is being acquired here for the lifetime of the
instance?

[pkalinnikov, 2016/11/17 15:24:31]

The resource is logical rather than physical. Resource = the launched timer,
awaiting to be finished.

Does "scoped" sound better?

+// logging the execution time to it upon destruction.
+// See: "base/metrics/histogram_macros_internal.h".
+//
+// Sample usage:
+//   void Function() {
+//     SCOPED_UMA_HISTOGRAM_THREAD_TIMER("Component.FunctionTime");
+//     ...
+//   }
+#define SCOPED_UMA_HISTOGRAM_THREAD_TIMER(name)                          \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER_EXPANDER(name, false, \
+                                                            __COUNTER__)
+
+// Same as SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h", but

[engedy, 2016/11/16 14:48:07]

nit: Similar to ...

[pkalinnikov, 2016/11/17 15:24:32]

Done.

+// measures time in microseconds, up to 100 milliseconds. Recommended for

[engedy, 2016/11/16 14:48:07]

Once we have measured the overhead, it would be nice to include a quick summary
of the numbers here.

Furthermore, if some platforms are prohibitively expensive, we should also
consider some kind of sampling-support.

+// measuring short delays with high precision.
+#define SCOPED_UMA_HISTOGRAM_MICRO_TIMER(name) \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_EXPANDER(name, __COUNTER__)
+
+// Same as SCOPED_UMA_HISTOGRAM_THREAD_TIMER, but measures time in microseconds,

[engedy, 2016/11/16 14:48:07]

Similar to SCOPED_UMA_HISTOGRAM_THREAD_TIMER above, ...

[pkalinnikov, 2016/11/17 15:24:32]

Done.

+// up to 100 milliseconds. Recommended for measuring short delays with high
+// precision, free of time spent for blocking operations.

[engedy, 2016/11/16 14:48:07]

nit: spent on

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+#define SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER(name)                   \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER_EXPANDER(name, true, \
+                                                            __COUNTER__)
+
+// Below are helpers used by other macros. Shouldn't be used directly. ---------
+
+// This is necessary to expand __COUNTER__ to an actual value.
+#define INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_EXPANDER(name, suffix) \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_UNIQUE(                      \
+      name, internal::TimeTicksProvider, true, suffix)
+
+// This is necessary to expand __COUNTER__ to an actual value.
+#define INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER_EXPANDER( \
+    name, is_micro, suffix)                                        \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_UNIQUE(                \
+      name, internal::ThreadTicksProvider, is_micro, suffix)
+
+// Creates a static histogram pointer and a RAII object referring to it, both
+// uniquely-named, using the unique |suffix| passed in.
+#define INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_UNIQUE(name, time_provider, \
+                                                         is_micro, suffix)    \
+  static base::HistogramBase* histogram_##suffix =                            \
+      base::Histogram::FactoryGet(                                            \
+          name, 1, is_micro ? 100000 : 10000, 50,                             \
+          base::HistogramBase::kUmaTargetedHistogramFlag);                    \
+  internal::ScopedHistogramTimer<time_provider, is_micro>                     \
+      scoped_histogram_timer_##suffix(histogram_##suffix);
+
+namespace internal {
+
+class TimeTicksProvider {
+ public:
+  static bool IsSupported() { return true; }
+  static base::TimeTicks Now() { return base::TimeTicks::Now(); }
+};
+
+using ThreadTicksProvider = base::ThreadTicks;

[engedy, 2016/11/16 14:48:07]

ThreadTicks seems to have WaitUntilInitialized(), which we probably need to call
in the ctor.

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+
+template <typename TimeProvider, bool is_micro>

[engedy, 2016/11/16 14:48:07]

nit: s/is_micro/is_microsec_precision/

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+class ScopedHistogramTimer {
+ public:
+  ScopedHistogramTimer(base::HistogramBase* histogram)
+      : histogram_(histogram),
+        construction_time_(TimeProvider::IsSupported() ? TimeProvider::Now()
+                                                       : TimeType()) {}
+
+  ~ScopedHistogramTimer() {
+    if (!TimeProvider::IsSupported())
+      return;
+    const base::TimeDelta delta = TimeProvider::Now() - construction_time_;
+    if (is_micro)
+      histogram_->Add(delta.InMicroseconds());
+    else
+      histogram_->Add(delta.InMilliseconds());
+  }
+
+ private:
+  using TimeType = decltype(TimeProvider::Now());

[engedy, 2016/11/16 14:48:07]

nit: Blank line after.

[pkalinnikov, 2016/11/17 15:24:31]

Done.

+  base::HistogramBase* histogram_;
+  TimeType construction_time_;
+};

[engedy, 2016/11/16 14:48:07]

nit: DISALLOW_COPY_AND_ASSIGN, and #include "base/macros.h"

[pkalinnikov, 2016/11/17 15:24:32]

Done.

+
+}  // namespace internal
+
+}  // namespace subresource_filter