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..82cb61da847932c3bccf96c9c9f3c95163d5948b
--- /dev/null
+++ b/components/subresource_filter/core/common/scoped_uma_histogram_timers.h
@@ -0,0 +1,125 @@
+// 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 macros for recording TimeTicks/ThreadTicks with
+// 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.
+
+#ifndef COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_UMA_HISTOGRAM_TIMERS_
+#define COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_UMA_HISTOGRAM_TIMERS_
+
+#include "base/macros.h"
+#include "base/metrics/histogram.h"
+#include "base/time/time.h"
+
+namespace subresource_filter {
+
+// Scoped class which logs how long the current thread has been doing actual
+// work during the lifetime of the instance, measured in milliseconds, as 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 has 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 scoped object referring to that histogram, and
+// logging the execution time to it upon destruction.
+// See: "base/metrics/histogram_macros_internal.h".

[Ilya Sherman, 2016/11/18 22:26:05]

Please document that names passed to the macro must be runtime constants.

[pkalinnikov, 2016/11/21 14:51:00]

Done.

+//
+// 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__)
+
+// Similar to SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h",
+// but measures time in microseconds, up to 100 milliseconds. Recommended for
+// measuring short delays with high precision.
+#define SCOPED_UMA_HISTOGRAM_MICRO_TIMER(name) \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_TIMER_EXPANDER(name, __COUNTER__)
+
+// Similar to SCOPED_UMA_HISTOGRAM_THREAD_TIMER above, but measures time in
+// microseconds, up to 100 milliseconds. Recommended for measuring short delays
+// with high precision, free of time spent on blocking operations.
+#define SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER(name)                   \
+  INTERNAL_SCOPED_UMA_HISTOGRAM_MICRO_THREAD_TIMER_EXPANDER(name, true, \
+                                                            __COUNTER__)

[Ilya Sherman, 2016/11/18 22:26:05]

nit: All of these macros pass __COUNTER__ -- could it just be referenced once
below, or does it work better to reference it in the outer macros?

[Ilya Sherman, 2016/11/18 22:26:05]

nit: I'd probably group the two THREAD_TIMERs together

[pkalinnikov, 2016/11/21 14:51:00]

Done.

[pkalinnikov, 2016/11/21 14:51:00]

As far as I understood from reading base/metrics/histogram_macros.h, there
should be an indirect call, because otherwise __COUNT__ won't be expanded. Do
you have a better idea on how to expand it in a unified manner, not to produce
*_EXPANDER macros for each individual macro?

+
+// 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 scoped 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,                             \

[Ilya Sherman, 2016/11/18 22:26:05]

I guess that constant propagation probably makes the is_micro ternary statement
actually just be a constant load?

[pkalinnikov, 2016/11/21 14:51:00]

Yes, I guess it should be optimized down to a constant.

+          base::HistogramBase::kUmaTargetedHistogramFlag);                    \

[Ilya Sherman, 2016/11/18 22:26:05]

I'm not sure that it's appropriate to use this directly in this way -- the
internal histogram macros are careful about memory barriers.  Why did you decide
on this approach, rather than something more akin to what's done for the
existing macros?

[pkalinnikov, 2016/11/21 14:51:00]

According to "base/metrics/histogram.h", the FactoryGet method is thread-safe.
Moreover, I found plenty of its direct usages in the codebase:
https://cs.chromium.org/search/?q=FactoryGet+-file:base/metrics&sq=package:ch...
.

Indeed, the code in histogram_macros_internal.h cares about memory
synchronization, but only for the sake of initializing and accessing the the
histogram pointer. In my case the pointer is safely operated on because of C++11
guarantees for static local variables. All the rest is guaranteed by Histogram*
classes.

I decided towards this approach, because: a. it decouples histogram obtaining
from its usage, therefore it doesn't generate a new class for each call-site,
unlike the macros provided in histogram_macros.h; b. it uses less macros
(templates are more readable and maintainable in my opinion).

Besides, I think that it wouldn't be bad to refactor the scoped class in
histogram_macros_internal.h in a similar manner. See also a similar
implementation in WebKit:
https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/Histo...

[Ilya Sherman, 2016/11/22 00:02:47]

That's fair, though I'd expect that most (and maybe even all) of the direct
usages are not concerned about thread-safety, because the code is guaranteed to
run on a single thread.
Okay.  I think this C++11 guarantee is worth calling out very explicitly in a
comment.  Are you sure that all of the platforms that we target are using C++11
toolchains that provide this guarantee?

[pkalinnikov, 2016/11/24 13:40:09]

Our usage is single-threaded as well.

I discussed it with engedy@, and we think that for us it's okay to have a
simplified single-threaded version, unless we want to put it to a shared place
like base/metrics.

I added comments to emphasize this.
According to the discussion here:
https://groups.google.com/a/chromium.org/d/msg/cxx/j5rFewBzSBQ/o46rwpJJBQAJ

In chromium builds static locals are deliberately *not* thread-safely
initialized (with certain compilation flags involved).

+  internal::ScopedHistogramTimer<time_provider, is_micro>                     \
+      scoped_histogram_timer_##suffix(histogram_##suffix);
+
+namespace internal {
+
+class TimeTicksProvider {
+ public:
+  static bool IsSupported() { return true; }
+  static void WaitUntilInitialized() {}
+  static base::TimeTicks Now() { return base::TimeTicks::Now(); }
+};
+
+using ThreadTicksProvider = base::ThreadTicks;
+
+template <typename TimeProvider, bool is_microsec_precision>
+class ScopedHistogramTimer {
+ public:
+  ScopedHistogramTimer(base::HistogramBase* histogram) : histogram_(histogram) {
+    if (TimeProvider::IsSupported()) {
+      TimeProvider::WaitUntilInitialized();
+      construction_time_ = TimeProvider::Now();
+    }
+  }
+
+  ~ScopedHistogramTimer() {
+    if (!TimeProvider::IsSupported())
+      return;
+    const base::TimeDelta delta = TimeProvider::Now() - construction_time_;
+    if (is_microsec_precision)
+      histogram_->Add(delta.InMicroseconds());
+    else
+      histogram_->Add(delta.InMilliseconds());
+  }
+
+ private:
+  using TimeType = decltype(TimeProvider::Now());
+
+  base::HistogramBase* histogram_;
+  TimeType construction_time_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedHistogramTimer);
+};
+
+}  // namespace internal
+
+}  // namespace subresource_filter
+
+#endif  // COMPONENTS_SUBRESOURCE_FILTER_CORE_COMMON_SCOPED_UMA_HISTOGRAM_TIMERS_