[Metrics] Introduce High-resolution timing histograms/macros.

Migrated two metrics to use new APIs and flagged other identified
histograms' descriptions to highlight issue on dashboards (I will
email relevant owners after this lands).
Relevant metrics list extracted from https://crbug.com/807615#c19

R=asvitkine@chromium.org, fdoray@chromium.org

Bug: 807615
Change-Id: I84f0f8fb5ca7fd3c5b43ba7209693b89928ade07
Reviewed-on: https://chromium-review.googlesource.com/1062830
Commit-Queue: Gabriel Charette <gab@chromium.org>
Reviewed-by: Scott Violet <sky@chromium.org>
Reviewed-by: Alexei Svitkine <asvitkine@chromium.org>
Reviewed-by: François Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/master@{#560704}

base/metrics/histogram.cc

@@ -268,6 +268,16 @@ HistogramBase* Histogram::FactoryTimeGet(const std::string& name,
                     flags);
 }
 
+HistogramBase* Histogram::FactoryMicrosecondsTimeGet(const std::string& name,
+                                                     TimeDelta minimum,
+                                                     TimeDelta maximum,
+                                                     uint32_t bucket_count,
+                                                     int32_t flags) {
+  return FactoryGet(name, static_cast<Sample>(minimum.InMicroseconds()),
+                    static_cast<Sample>(maximum.InMicroseconds()), bucket_count,
+                    flags);
+}
+
 HistogramBase* Histogram::FactoryGet(const char* name,
                                      Sample minimum,
                                      Sample maximum,
@@ -285,6 +295,15 @@ HistogramBase* Histogram::FactoryTimeGet(const char* name,
                         flags);
 }
 
+HistogramBase* Histogram::FactoryMicrosecondsTimeGet(const char* name,
+                                                     TimeDelta minimum,
+                                                     TimeDelta maximum,
+                                                     uint32_t bucket_count,
+                                                     int32_t flags) {
+  return FactoryMicrosecondsTimeGet(std::string(name), minimum, maximum,
+                                    bucket_count, flags);
+}
+
 std::unique_ptr<HistogramBase> Histogram::PersistentCreate(
     const char* name,
     Sample minimum,

base/metrics/histogram.h

@@ -125,10 +125,15 @@ class BASE_EXPORT Histogram : public HistogramBase {
                                        base::TimeDelta maximum,
                                        uint32_t bucket_count,
                                        int32_t flags);
-
-  // Overloads of the above two functions that take a const char* |name| param,
-  // to avoid code bloat from the std::string constructor being inlined into
-  // call sites.
+  static HistogramBase* FactoryMicrosecondsTimeGet(const std::string& name,
+                                                   base::TimeDelta minimum,
+                                                   base::TimeDelta maximum,
+                                                   uint32_t bucket_count,
+                                                   int32_t flags);
+
+  // Overloads of the above functions that take a const char* |name| param, to
+  // avoid code bloat from the std::string constructor being inlined into call
+  // sites.
   static HistogramBase* FactoryGet(const char* name,
                                    Sample minimum,
                                    Sample maximum,
@@ -139,6 +144,11 @@ class BASE_EXPORT Histogram : public HistogramBase {
                                        base::TimeDelta maximum,
                                        uint32_t bucket_count,
                                        int32_t flags);
+  static HistogramBase* FactoryMicrosecondsTimeGet(const char* name,
+                                                   base::TimeDelta minimum,
+                                                   base::TimeDelta maximum,
+                                                   uint32_t bucket_count,
+                                                   int32_t flags);
 
   // Create a histogram using data in persistent storage.
   static std::unique_ptr<HistogramBase> PersistentCreate(

base/metrics/histogram_base.cc

@@ -112,10 +112,18 @@ void HistogramBase::AddKiB(Sample value, int count) {
   AddScaled(value, count, 1024);
 }
 
-void HistogramBase::AddTime(const TimeDelta& time) {
+void HistogramBase::AddTimeMillisecondsGranularity(const TimeDelta& time) {
   Add(static_cast<Sample>(time.InMilliseconds()));
 }
 
+void HistogramBase::AddTimeMicrosecondsGranularity(const TimeDelta& time) {
+  // Intentionally drop high-resolution reports on clients with low-resolution
+  // clocks. High-resolution metrics cannot make use of low-resolution data and
+  // reporting it merely adds noise to the metric. https://crbug.com/807615#c16
+  if (TimeTicks::IsHighResolution())
+    Add(static_cast<Sample>(time.InMicroseconds()));
+}
+
 void HistogramBase::AddBoolean(bool value) {
   Add(value ? 1 : 0);
 }

base/metrics/histogram_base.h

@@ -189,8 +189,12 @@ class BASE_EXPORT HistogramBase {
   void AddKilo(Sample value, int count);  // scale=1000
   void AddKiB(Sample value, int count);   // scale=1024
 
-  // 2 convenient functions that call Add(Sample).
-  void AddTime(const TimeDelta& time);
+  // Convenient functions that call Add(Sample).
+  void AddTime(const TimeDelta& time) { AddTimeMillisecondsGranularity(time); }
+  void AddTimeMillisecondsGranularity(const TimeDelta& time);
+  // Note: AddTimeMicrosecondsGranularity() drops the report if this client
+  // doesn't have a high-resolution clock.
+  void AddTimeMicrosecondsGranularity(const TimeDelta& time);
   void AddBoolean(bool value);
 
   virtual void AddSamples(const HistogramSamples& samples) = 0;

base/metrics/histogram_functions.cc

@@ -71,7 +71,7 @@ void UmaHistogramCustomTimes(const std::string& name,
                              int buckets) {
   HistogramBase* histogram = Histogram::FactoryTimeGet(
       name, min, max, buckets, HistogramBase::kUmaTargetedHistogramFlag);
-  histogram->AddTime(sample);
+  histogram->AddTimeMillisecondsGranularity(sample);
 }
 
 void UmaHistogramTimes(const std::string& name, TimeDelta sample) {

base/metrics/histogram_macros.h

@@ -178,7 +178,8 @@
 // Sample usage:
 //   UMA_HISTOGRAM_TIMES("My.Timing.Histogram", time_delta);
 
-// Short timings - up to 10 seconds.
+// Short timings - up to 10 seconds. For high-resolution (microseconds) timings,
+// see UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES.
 #define UMA_HISTOGRAM_TIMES(name, sample) UMA_HISTOGRAM_CUSTOM_TIMES(          \
     name, sample, base::TimeDelta::FromMilliseconds(1),                        \
     base::TimeDelta::FromSeconds(10), 50)
@@ -206,10 +207,32 @@
 // Sample usage:
 //   UMA_HISTOGRAM_CUSTOM_TIMES("Very.Long.Timing.Histogram", time_delta,
 //       base::TimeDelta::FromSeconds(1), base::TimeDelta::FromDays(1), 100);
-#define UMA_HISTOGRAM_CUSTOM_TIMES(name, sample, min, max, bucket_count)       \
-    STATIC_HISTOGRAM_POINTER_BLOCK(name, AddTime(sample),                      \
-        base::Histogram::FactoryTimeGet(name, min, max, bucket_count,          \
-            base::HistogramBase::kUmaTargetedHistogramFlag))
+#define UMA_HISTOGRAM_CUSTOM_TIMES(name, sample, min, max, bucket_count) \
+  STATIC_HISTOGRAM_POINTER_BLOCK(                                        \
+      name, AddTimeMillisecondsGranularity(sample),                      \
+      base::Histogram::FactoryTimeGet(                                   \
+          name, min, max, bucket_count,                                  \
+          base::HistogramBase::kUmaTargetedHistogramFlag))
+
+// Same as UMA_HISTOGRAM_CUSTOM_TIMES but reports |sample| in microseconds,
+// dropping the report if this client doesn't have a high-resolution clock.
+//
+// Note: dropping reports on clients with low-resolution clocks means these
+// reports will be biased to a portion of the population on Windows. See
+// Windows.HasHighResolutionTimeTicks for the affected sample.
+//
+// Sample usage:
+//  UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+//      "High.Resolution.TimingMicroseconds.Histogram", time_delta,
+//      base::TimeDelta::FromMicroseconds(1),
+//      base::TimeDelta::FromMilliseconds(10), 100);
+#define UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(name, sample, min, max, \
+                                                bucket_count)           \
+  STATIC_HISTOGRAM_POINTER_BLOCK(                                       \
+      name, AddTimeMicrosecondsGranularity(sample),                     \
+      base::Histogram::FactoryMicrosecondsTimeGet(                      \
+          name, min, max, bucket_count,                                 \
+          base::HistogramBase::kUmaTargetedHistogramFlag))
 
 // Scoped class which logs its time on this earth as a UMA statistic. This is
 // recommended for when you want a histogram which measures the time it takes

base/metrics/histogram_macros_local.h

@@ -64,10 +64,11 @@
     name, sample, base::TimeDelta::FromMilliseconds(1),                        \
     base::TimeDelta::FromSeconds(10), 50)
 
-#define LOCAL_HISTOGRAM_CUSTOM_TIMES(name, sample, min, max, bucket_count)     \
-    STATIC_HISTOGRAM_POINTER_BLOCK(name, AddTime(sample),                      \
-        base::Histogram::FactoryTimeGet(name, min, max, bucket_count,          \
-                                        base::HistogramBase::kNoFlags))
+#define LOCAL_HISTOGRAM_CUSTOM_TIMES(name, sample, min, max, bucket_count) \
+  STATIC_HISTOGRAM_POINTER_BLOCK(                                          \
+      name, AddTimeMillisecondsGranularity(sample),                        \
+      base::Histogram::FactoryTimeGet(name, min, max, bucket_count,        \
+                                      base::HistogramBase::kNoFlags))
 
 //------------------------------------------------------------------------------
 // Memory histograms.

base/task_scheduler/task_tracker.cc

@@ -85,8 +85,7 @@ HistogramBase* GetLatencyHistogram(StringPiece histogram_name,
   DCHECK(!histogram_name.empty());
   DCHECK(!histogram_label.empty());
   DCHECK(!task_type_suffix.empty());
-  // Mimics the UMA_HISTOGRAM_TIMES macro except we don't specify bounds with
-  // TimeDeltas as FactoryTimeGet assumes millisecond granularity. The minimums
+  // Mimics the UMA_HISTOGRAM_HIGH_RESOLUTION_CUSTOM_TIMES macro. The minimums
   // and maximums were chosen to place the 1ms mark at around the 70% range
   // coverage for buckets giving us good info for tasks that have a latency
   // below 1ms (most of them) and enough info to assess how bad the latency is
@@ -94,8 +93,10 @@ HistogramBase* GetLatencyHistogram(StringPiece histogram_name,
   const std::string histogram = JoinString(
       {"TaskScheduler", histogram_name, histogram_label, task_type_suffix},
       ".");
-  return Histogram::FactoryGet(histogram, 1, 20000, 50,
-                               HistogramBase::kUmaTargetedHistogramFlag);
+  return Histogram::FactoryMicrosecondsTimeGet(
+      histogram, TimeDelta::FromMicroseconds(1),
+      TimeDelta::FromMilliseconds(20), 50,
+      HistogramBase::kUmaTargetedHistogramFlag);
 }
 
 // Upper bound for the
@@ -461,7 +462,7 @@ void TaskTracker::RecordLatencyHistogram(
             [task_traits.may_block() || task_traits.with_base_sync_primitives()
                  ? 1
                  : 0]
-                ->Add(task_latency.InMicroseconds());
+                ->AddTimeMicrosecondsGranularity(task_latency);
 }
 
 void TaskTracker::RunOrSkipTask(Task task,

chromecast/base/metrics/cast_histograms.h

@@ -22,11 +22,13 @@
     histogram_pointer->histogram_add_method_invocation;                        \
   } while (0)
 
-#define UMA_HISTOGRAM_CUSTOM_TIMES_NO_CACHE( \
-    name, sample, min, max, bucket_count) \
-    STATIC_HISTOGRAM_POINTER_BLOCK_NO_CACHE(name, AddTime(sample), \
-        base::Histogram::FactoryTimeGet(name, min, max, bucket_count, \
-            base::Histogram::kUmaTargetedHistogramFlag))
+#define UMA_HISTOGRAM_CUSTOM_TIMES_NO_CACHE(name, sample, min, max, \
+                                            bucket_count)           \
+  STATIC_HISTOGRAM_POINTER_BLOCK_NO_CACHE(                          \
+      name, AddTimeMillisecondsGranularity(sample),                 \
+      base::Histogram::FactoryTimeGet(                              \
+          name, min, max, bucket_count,                             \
+          base::Histogram::kUmaTargetedHistogramFlag))
 
 #define UMA_HISTOGRAM_CUSTOM_COUNTS_NO_CACHE(name, sample, min, max, \
                                              bucket_count, count) \

ui/aura_extra/window_occlusion_impl_win.cc

@@ -182,10 +182,11 @@ ComputeNativeWindowOcclusionStatusImpl(
   if (window_evaluator.HasAtLeastOneVisibleWindow())
     iterator->Iterate(&window_evaluator);
 
-  // Record the duration of the call to ComputeNativeWindowOcclusionStatus().
-  base::TimeDelta duration = base::TimeTicks::Now() - calculation_start_time;
-  UMA_HISTOGRAM_COUNTS_10M("Windows.ComputeNativeWindowOcclusionTime",
-                           duration.InMicroseconds());
+  UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+      "Windows.ComputeNativeWindowOcclusionTime",
+      base::TimeTicks::Now() - calculation_start_time,
+      base::TimeDelta::FromMicroseconds(1), base::TimeDelta::FromSeconds(10),
+      50);
 
   return window_evaluator.TakeResult();
 }