Record the TaskLatency Histogram in Microseconds Instead of Milliseconds

base/task_scheduler/task_tracker.cc

 // 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.
 
 #include "base/task_scheduler/task_tracker.h"
 
 #include <limits>
 #include <string>
 
 #include "base/callback.h"
@@ skipping 56 matching lines @@
   out->append(tmp);
 }
 
 const char kQueueFunctionName[] = "base::PostTask";
 
 // This name conveys that a Task is run by the task scheduler without revealing
 // its implementation details.
 const char kRunFunctionName[] = "TaskSchedulerRunTask";
 
 HistogramBase* GetTaskLatencyHistogram(const char* suffix) {
-  // Mimics the UMA_HISTOGRAM_TIMES macro.
-  return Histogram::FactoryTimeGet(
-      std::string("TaskScheduler.TaskLatency.") + suffix,
-      TimeDelta::FromMilliseconds(1), TimeDelta::FromSeconds(10), 50,
-      HistogramBase::kUmaTargetedHistogramFlag);
+  // Mimics the UMA_HISTOGRAM_TIMES macro except we don't specify bounds with
+  // TimeDeltas as FactoryTimeGet assumes millisecond granularity.
+  return Histogram::FactoryGet(
+      std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000,

[gab, 2017/04/28 01:49:29]

2000 max is merely 2ms, I think we want something like 20ms? The logarithmic
buckets will provide a nice curve in the early buckets anyways

[robliao, 2017/04/28 17:07:53]

2ms covers 89-99% of the 7 day aggregation on Windows+canary. I figure if it was
longer than that, then we have something more interesting to consider. Thoughts?

[robliao, 2017/04/28 17:18:47]

Inlining gab@'s reply to the thread:

Is that true even for Background blocking though?
If things do regress beyond that it'd be nice to know by how much, so
having a bit of a buffer is free and useful?

[robliao, 2017/04/28 17:23:41]

So for background blocking the data is approximately as follows:

ms
  [0-1) 89%
  [1-2) 91%
  [2-4) 93%
  [4-7) 94%
 [7-14) 95%
[14-34) 96%

20ms would get us more information on about 5% of hits compared to 2ms.


Contrasting that to UserBlocking MayBlock:
  [0-3) 99%

20ms certainly seems like too much for this histogram.

[robliao, 2017/04/28 17:57:38]

Inlining gab@'s reply to this thread:
But so long as we use logarithmic buckets it's fine, extending the range will
pickup more stuff (think long term, not just current stats mid-migration) while
not significantly reducing signal in lower buckets.

[robliao, 2017/04/28 18:17:59]

Longer term, I would expect these values to go down as things get faster. 

For reference these are the ranges to 2000us
Bucket: Max Bucket Value
 1 : 01
 2 : 02
 3 : 03
 4 : 04
 5 : 05
 6 : 06
 7 : 07
 8 : 08
 9 : 09
10 : 10
11 : 11
12 : 13
13 : 15
14 : 17
15 : 19
16 : 22
17 : 25
18 : 29
19 : 33
20 : 38
21 : 44
22 : 50
23 : 57
24 : 65
25 : 75
26 : 86
27 : 99
28 : 113
29 : 130
30 : 149
31 : 171
32 : 196
33 : 225
34 : 258
35 : 296
36 : 339
37 : 389
38 : 446
39 : 511
40 : 586
41 : 672
42 : 770
43 : 882
44 : 1011 **************************** 1ms boundary
45 : 1159
46 : 1328
47 : 1522
48 : 1745
49 : 2000

And these are the ranges to 20000
Bucket: Max Bucket Value
 1 : 01
 2 : 02
 3 : 03
 4 : 04
 5 : 05
 6 : 06
 7 : 07
 8 : 08
 9 : 10
10 : 12
11 : 15
12 : 18
13 : 22
14 : 27
15 : 33
16 : 40
17 : 48
18 : 58
19 : 70
20 : 85
21 : 103
22 : 124
23 : 150
24 : 181
25 : 218
26 : 263
27 : 317
28 : 383
29 : 462
30 : 558
31 : 674
32 : 814
33 : 983
34 : 1187  **************************** 1ms boundary
35 : 1433
36 : 1730
37 : 2088
38 : 2521
39 : 3043
40 : 3673
41 : 4434
42 : 5353
43 : 6462
44 : 7801
45 : 9417
46 : 11368
47 : 13724
48 : 16567
49 : 20000

If we're happy with how 20000 looks, I'll go ahead and change it. It's a
difference of about 10 bucket positions.

I guess it comes down to where we want to place the 1ms mark:
0-2000   = 88% of Max Buckets
0-20000  = 68% of Max Buckets
0-200000 = 54% of Max Buckets

+      50, HistogramBase::kUmaTargetedHistogramFlag);
 }
 
 // Upper bound for the
 // TaskScheduler.BlockShutdownTasksPostedDuringShutdown histogram.
 const HistogramBase::Sample kMaxBlockShutdownTasksPostedDuringShutdown = 1000;
 
 void RecordNumBlockShutdownTasksPostedDuringShutdown(
     HistogramBase::Sample value) {
   UMA_HISTOGRAM_CUSTOM_COUNTS(
       "TaskScheduler.BlockShutdownTasksPostedDuringShutdown", value, 1,
@@ skipping 396 matching lines @@
   }
 }
 
 void TaskTracker::RecordTaskLatencyHistogram(Task* task) {
   const TimeDelta task_latency = TimeTicks::Now() - task->sequenced_time;
   task_latency_histograms_[static_cast<int>(task->traits.priority())]
                           [task->traits.may_block() ||
                                    task->traits.with_base_sync_primitives()
                                ? 1
                                : 0]
-                              ->AddTime(task_latency);
+                              ->Add(task_latency.InMicroseconds());
 }
 
 }  // namespace internal
 }  // namespace base