Chromium Code Reviews
|
|
Chromium Code Reviews
Issue
2839333002:
Record the TaskLatency Histogram in Microseconds Instead of Milliseconds (Closed)
|
Created:
3 years, 7 months ago by robliao Modified:
3 years, 7 months ago CC:
chromium-reviews, vmpstr+watch_chromium.org, robliao+watch_chromium.org, gab+watch_chromium.org, asvitkine+watch_chromium.org, fdoray+watch_chromium.org, danakj+watch_chromium.org Target Ref:
refs/heads/master Project:
chromium Visibility:
Public. |
DescriptionRecord the TaskLatency Histogram in Microseconds Instead of Milliseconds
Most task latencies were between 0 and 1 ms. Recording task latencies
in microseconds will provide better data
BUG=715777
Review-Url: https://codereview.chromium.org/2839333002
Cr-Commit-Position: refs/heads/master@{#468135}
Committed: https://chromium.googlesource.com/chromium/src/+/180f23bbfdd91ade1b232094a17e48a4e590f38d
Patch Set 1 #
Total comments: 10
Patch Set 2 : CR Feedback #
Total comments: 6
Patch Set 3 : CR Feedback #
Messages
Total messages: 47 (24 generated)
Description was changed from ========== Record TaskLatency in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 ========== to ========== Record TaskLatency in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 ==========
robliao@chromium.org changed reviewers: + fdoray@chromium.org, gab@chromium.org
Description was changed from ========== Record TaskLatency in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 ========== to ========== Record the TaskLatency Histogram in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 ==========
Here's what this histogram looks like now:
Histogram:
TaskScheduler.TaskLatencyMicroseconds.UserBlockingTaskPriority.MayBlock recorded
138 samples, mean = 92.3 (flags = 0x1)
0 ...
38 --O
(1 = 0.7%) {0.0%}
44 --O
(1 = 0.7%) {0.7%}
50 --------------O
(8 = 5.8%) {1.4%}
57 -----------------------O
(13 = 9.4%) {7.2%}
65 ----------------------------------------O
(23 = 16.7%) {16.7%}
75 ------------------------------------------------------------------------O
(41 = 29.7%) {33.3%}
86 ------------------------------------------------------------O
(34 = 24.6%) {63.0%}
99 ----------------O
(9 = 6.5%) {87.7%}
113 -------O
(4 = 2.9%) {94.2%}
130 ----O
(2 = 1.4%) {97.1%}
149 ...
296 --O
(1 = 0.7%) {98.6%}
339 ...
1328 --O
(1 = 0.7%) {99.3%}
1522 ...
The CQ bit was checked by robliao@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at: https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: Try jobs failed on following builders: linux_android_rel_ng on master.tryserver.chromium.android (JOB_FAILED, https://build.chromium.org/p/tryserver.chromium.android/builders/linux_androi...)
lgtm
The CQ bit was checked by robliao@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at: https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
robliao@chromium.org changed reviewers: + isherman@chromium.org
isherman: Please review tools/metrics/histograms/histograms.xml. Thanks!
Metrics LGTM % comments: https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); While you're here, would you mind updating this code to use UmaHistogramTimes() rather than getting into the FactoryGet calls directly? https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:74316: +<histogram name="TaskScheduler.TaskLatencyMicroseconds" units="microseconds"> nit: Mebbe mark as base="true" -- there's no data emitted to this histogram directly, right? https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:127474: + </obsolete> nit: I think it's fine to just mark the base histogram as obsolete; it should bubble up to the rest.
https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); On 2017/04/27 21:24:01, Ilya Sherman wrote: > While you're here, would you mind updating this code to use UmaHistogramTimes() > rather than getting into the FactoryGet calls directly? UmaHistogramTimes starts at 1ms minimum time sample, no? https://cs.chromium.org/chromium/src/base/metrics/histogram_functions.h?l=87 https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:74316: +<histogram name="TaskScheduler.TaskLatencyMicroseconds" units="microseconds"> On 2017/04/27 21:24:01, Ilya Sherman wrote: > nit: Mebbe mark as base="true" -- there's no data emitted to this histogram > directly, right? Yep. Done. https://codereview.chromium.org/2839333002/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:127474: + </obsolete> On 2017/04/27 21:24:01, Ilya Sherman wrote: > nit: I think it's fine to just mark the base histogram as obsolete; it should > bubble up to the rest. Done.
https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); On 2017/04/27 21:42:22, robliao wrote: > On 2017/04/27 21:24:01, Ilya Sherman wrote: > > While you're here, would you mind updating this code to use > UmaHistogramTimes() > > rather than getting into the FactoryGet calls directly? > > UmaHistogramTimes starts at 1ms minimum time sample, no? > https://cs.chromium.org/chromium/src/base/metrics/histogram_functions.h?l=87 Yes, sorry, you're right. I meant UmaHistogramCustomTimes().
https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); On 2017/04/27 21:50:35, Ilya Sherman wrote: > On 2017/04/27 21:42:22, robliao wrote: > > On 2017/04/27 21:24:01, Ilya Sherman wrote: > > > While you're here, would you mind updating this code to use > > UmaHistogramTimes() > > > rather than getting into the FactoryGet calls directly? > > > > UmaHistogramTimes starts at 1ms minimum time sample, no? > > https://cs.chromium.org/chromium/src/base/metrics/histogram_functions.h?l=87 > > Yes, sorry, you're right. I meant UmaHistogramCustomTimes(). UmaHistogramCustomTimes -> HistogramBase* histogram = Histogram::FactoryTimeGet( name, min, max, buckets, HistogramBase::kUmaTargetedHistogramFlag); This leads to return FactoryGet(name, static_cast<Sample(minimum.InMilliseconds()), static_cast<Sample>(maximum.InMilliseconds()), bucket_count, flags); I wasn't able to find a Uma* Time Histogram function that handled microseconds, which is why I went directly to FactoryGet.
https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); On 2017/04/27 21:54:49, robliao wrote: > On 2017/04/27 21:50:35, Ilya Sherman wrote: > > On 2017/04/27 21:42:22, robliao wrote: > > > On 2017/04/27 21:24:01, Ilya Sherman wrote: > > > > While you're here, would you mind updating this code to use > > > UmaHistogramTimes() > > > > rather than getting into the FactoryGet calls directly? > > > > > > UmaHistogramTimes starts at 1ms minimum time sample, no? > > > https://cs.chromium.org/chromium/src/base/metrics/histogram_functions.h?l=87 > > > > Yes, sorry, you're right. I meant UmaHistogramCustomTimes(). > > UmaHistogramCustomTimes -> > HistogramBase* histogram = Histogram::FactoryTimeGet( > name, min, max, buckets, HistogramBase::kUmaTargetedHistogramFlag); > > This leads to > return FactoryGet(name, static_cast<Sample(minimum.InMilliseconds()), > static_cast<Sample>(maximum.InMilliseconds()), bucket_count, flags); > > I wasn't able to find a Uma* Time Histogram function that handled microseconds, > which is why I went directly to FactoryGet. Ah, I see. How about UmaHistogramCustomCounts? It's not really super important, tbh. Someday we might want to hide kUmaTargetedHistogramFlag as a non-leaky implementation detail; but if you prefer FactoryGet for now, that's fine too.
https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/1/base/task_scheduler/task_tr... base/task_scheduler/task_tracker.cc:81: 50, HistogramBase::kUmaTargetedHistogramFlag); On 2017/04/27 21:56:45, Ilya Sherman wrote: > On 2017/04/27 21:54:49, robliao wrote: > > On 2017/04/27 21:50:35, Ilya Sherman wrote: > > > On 2017/04/27 21:42:22, robliao wrote: > > > > On 2017/04/27 21:24:01, Ilya Sherman wrote: > > > > > While you're here, would you mind updating this code to use > > > > UmaHistogramTimes() > > > > > rather than getting into the FactoryGet calls directly? > > > > > > > > UmaHistogramTimes starts at 1ms minimum time sample, no? > > > > > https://cs.chromium.org/chromium/src/base/metrics/histogram_functions.h?l=87 > > > > > > Yes, sorry, you're right. I meant UmaHistogramCustomTimes(). > > > > UmaHistogramCustomTimes -> > > HistogramBase* histogram = Histogram::FactoryTimeGet( > > name, min, max, buckets, HistogramBase::kUmaTargetedHistogramFlag); > > > > This leads to > > return FactoryGet(name, static_cast<Sample(minimum.InMilliseconds()), > > static_cast<Sample>(maximum.InMilliseconds()), bucket_count, flags); > > > > I wasn't able to find a Uma* Time Histogram function that handled > microseconds, > > which is why I went directly to FactoryGet. > > Ah, I see. How about UmaHistogramCustomCounts? > > It's not really super important, tbh. Someday we might want to hide > kUmaTargetedHistogramFlag as a non-leaky implementation detail; but if you > prefer FactoryGet for now, that's fine too. Gotcha. We also keep the histogram around so we don't have to call FactoryGet() so I will leave it as is. The UmaHistogram* calls requery for the histogram every time.
The CQ bit was checked by robliao@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at: https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
lgtm w/ comment https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, 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
https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, On 2017/04/28 01:49:29, gab wrote: > 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 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?
Is that true even for Background blocking though? On Fri, Apr 28, 2017, 13:07 <robliao@chromium.org> wrote: > > > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > File base/task_scheduler/task_tracker.cc (right): > > > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > base/task_scheduler/task_tracker.cc:80: > std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, > On 2017/04/28 01:49:29, gab wrote: > > 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 > > 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? > > https://codereview.chromium.org/2839333002/ > -- You received this message because you are subscribed to the Google Groups "Chromium-reviews" group. To unsubscribe from this group and stop receiving emails from it, send an email to chromium-reviews+unsubscribe@chromium.org.
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? On Fri, Apr 28, 2017, 13:12 Gabriel Charette <gab@google.com> wrote: > Is that true even for Background blocking though? > > On Fri, Apr 28, 2017, 13:07 <robliao@chromium.org> wrote: > >> >> >> https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... >> File base/task_scheduler/task_tracker.cc (right): >> >> >> https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... >> base/task_scheduler/task_tracker.cc:80: >> std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, >> On 2017/04/28 01:49:29, gab wrote: >> > 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 >> >> 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? >> >> https://codereview.chromium.org/2839333002/ >> > -- You received this message because you are subscribed to the Google Groups "Chromium-reviews" group. To unsubscribe from this group and stop receiving emails from it, send an email to chromium-reviews+unsubscribe@chromium.org.
https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, On 2017/04/28 17:07:53, robliao wrote: > On 2017/04/28 01:49:29, gab wrote: > > 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 > > 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? 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?
https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, On 2017/04/28 17:18:47, robliao wrote: > On 2017/04/28 17:07:53, robliao wrote: > > On 2017/04/28 01:49:29, gab wrote: > > > 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 > > > > 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? > > 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? 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.
On 2017/04/28 17:23:42, robliao wrote: > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > File base/task_scheduler/task_tracker.cc (right): > > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > base/task_scheduler/task_tracker.cc:80: > std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, > On 2017/04/28 17:18:47, robliao wrote: > > On 2017/04/28 17:07:53, robliao wrote: > > > On 2017/04/28 01:49:29, gab wrote: > > > > 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 > > > > > > 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? > > > > 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? > > 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. 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.
https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, On 2017/04/28 17:23:41, robliao wrote: > On 2017/04/28 17:18:47, robliao wrote: > > On 2017/04/28 17:07:53, robliao wrote: > > > On 2017/04/28 01:49:29, gab wrote: > > > > 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 > > > > > > 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? > > > > 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? > > 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. 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.
https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... File base/task_scheduler/task_tracker.cc (right): https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... base/task_scheduler/task_tracker.cc:80: std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, On 2017/04/28 17:57:38, robliao wrote: > On 2017/04/28 17:23:41, robliao wrote: > > On 2017/04/28 17:18:47, robliao wrote: > > > On 2017/04/28 17:07:53, robliao wrote: > > > > On 2017/04/28 01:49:29, gab wrote: > > > > > 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 > > > > > > > > 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? > > > > > > 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? > > > > 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. > > 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. 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
On 2017/04/28 18:17:59, robliao wrote: > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > File base/task_scheduler/task_tracker.cc (right): > > https://codereview.chromium.org/2839333002/diff/20001/base/task_scheduler/tas... > base/task_scheduler/task_tracker.cc:80: > std::string("TaskScheduler.TaskLatencyMicroseconds.") + suffix, 1, 2000, > On 2017/04/28 17:57:38, robliao wrote: > > On 2017/04/28 17:23:41, robliao wrote: > > > On 2017/04/28 17:18:47, robliao wrote: > > > > On 2017/04/28 17:07:53, robliao wrote: > > > > > On 2017/04/28 01:49:29, gab wrote: > > > > > > 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 > > > > > > > > > > 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? > > > > > > > > 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? > > > > > > 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. > > > > 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. > > 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 Thanks for the breakdowns, 20000 looks fine grain enough to me
Adjusted to 20000us
Here's what the histogram looks like now:
Histogram:
TaskScheduler.TaskLatencyMicroseconds.UserVisibleTaskPriority.MayBlock recorded
176 samples, mean = 2953.4 (flags = 0x1)
0 ...
27 -----------------O
(7 = 4.0%) {0.0%}
33 ----------------------O
(9 = 5.1%) {4.0%}
40 ------------------------O
(10 = 5.7%) {9.1%}
48 -----------------------------------------------------------------O
(27 = 15.3%) {14.8%}
58 -----------------------------------------------------O
(22 = 12.5%) {30.1%}
70 ------------------------------------------------------------------------O
(30 = 17.0%) {42.6%}
85 --------------------------------------------------------------O
(26 = 14.8%) {59.7%}
103 ------------------------O
(10 = 5.7%) {74.4%}
124 --------------O
(6 = 3.4%) {80.1%}
150 ----------O
(4 = 2.3%) {83.5%}
181 --O
(1 = 0.6%) {85.8%}
218 -------O
(3 = 1.7%) {86.4%}
263 O
(0 = 0.0%) {88.1%}
317 ----------O
(4 = 2.3%) {88.1%}
383 O
(0 = 0.0%) {90.3%}
462 --O
(1 = 0.6%) {90.3%}
558 --O
(1 = 0.6%) {90.9%}
674 --O
(1 = 0.6%) {91.5%}
814 O
(0 = 0.0%) {92.0%}
983 --O
(1 = 0.6%) {92.0%}
1187 ...
2088 --O
(1 = 0.6%) {92.6%}
2521 ...
6462 -----O
(2 = 1.1%) {93.2%}
7801 ...
20000 ------------------------O
(10 = 5.7%) {94.3%}
The CQ bit was checked by robliao@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at: https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
On 2017/04/28 19:42:36, robliao wrote:
> Adjusted to 20000us
>
> Here's what the histogram looks like now:
> Histogram:
> TaskScheduler.TaskLatencyMicroseconds.UserVisibleTaskPriority.MayBlock
recorded
> 176 samples, mean = 2953.4 (flags = 0x1)
> 0 ...
> 27 -----------------O
> (7 = 4.0%) {0.0%}
> 33 ----------------------O
> (9 = 5.1%) {4.0%}
> 40 ------------------------O
> (10 = 5.7%) {9.1%}
> 48 -----------------------------------------------------------------O
> (27 = 15.3%) {14.8%}
> 58 -----------------------------------------------------O
> (22 = 12.5%) {30.1%}
> 70
------------------------------------------------------------------------O
> (30 = 17.0%) {42.6%}
> 85 --------------------------------------------------------------O
> (26 = 14.8%) {59.7%}
> 103 ------------------------O
> (10 = 5.7%) {74.4%}
> 124 --------------O
> (6 = 3.4%) {80.1%}
> 150 ----------O
> (4 = 2.3%) {83.5%}
> 181 --O
> (1 = 0.6%) {85.8%}
> 218 -------O
> (3 = 1.7%) {86.4%}
> 263 O
> (0 = 0.0%) {88.1%}
> 317 ----------O
> (4 = 2.3%) {88.1%}
> 383 O
> (0 = 0.0%) {90.3%}
> 462 --O
> (1 = 0.6%) {90.3%}
> 558 --O
> (1 = 0.6%) {90.9%}
> 674 --O
> (1 = 0.6%) {91.5%}
> 814 O
> (0 = 0.0%) {92.0%}
> 983 --O
> (1 = 0.6%) {92.0%}
> 1187 ...
> 2088 --O
> (1 = 0.6%) {92.6%}
> 2521 ...
> 6462 -----O
> (2 = 1.1%) {93.2%}
> 7801 ...
> 20000 ------------------------O
> (10 = 5.7%) {94.3%}
lgtm
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
The CQ bit was checked by robliao@chromium.org
The patchset sent to the CQ was uploaded after l-g-t-m from isherman@chromium.org, fdoray@chromium.org Link to the patchset: https://codereview.chromium.org/2839333002/#ps40001 (title: "CR Feedback")
CQ is trying da patch. Follow status at: https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
CQ is committing da patch.
Bot data: {"patchset_id": 40001, "attempt_start_ts": 1493414795865050,
"parent_rev": "17c53cea08706b1c1a280aac583d8fbef66d18d4", "commit_rev":
"180f23bbfdd91ade1b232094a17e48a4e590f38d"}
Message was sent while issue was closed.
Description was changed from ========== Record the TaskLatency Histogram in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 ========== to ========== Record the TaskLatency Histogram in Microseconds Instead of Milliseconds Most task latencies were between 0 and 1 ms. Recording task latencies in microseconds will provide better data BUG=715777 Review-Url: https://codereview.chromium.org/2839333002 Cr-Commit-Position: refs/heads/master@{#468135} Committed: https://chromium.googlesource.com/chromium/src/+/180f23bbfdd91ade1b232094a17e... ==========
Message was sent while issue was closed.
Committed patchset #3 (id:40001) as https://chromium.googlesource.com/chromium/src/+/180f23bbfdd91ade1b232094a17e... |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
