Chromium Code Reviews
|
|
Chromium Code Reviews
Issue
2503283003:
Add high-precision timing histograms. (Closed)
|
Created:
4 years, 1 month ago by pkalinnikov Modified:
4 years ago CC:
chromium-reviews, mlamouri+watch-content_chromium.org, jam, darin-cc_chromium.org, asvitkine+watch_chromium.org, rkaplow Target Ref:
refs/pending/heads/master Project:
chromium Visibility:
Public. |
DescriptionAdd high-precision timing histograms.
BUG=609747
Committed: https://crrev.com/7c84dd6c2273cea47031237046ec001ac7fb75ea
Cr-Commit-Position: refs/heads/master@{#435890}
Patch Set 1 #
Total comments: 31
Patch Set 2 : Address comments of engedy@ #
Total comments: 18
Patch Set 3 : Modify BUILD file. Address comments from isherman@. #Patch Set 4 : Add comment; put microseconds to pretty_print. #Patch Set 5 : rebase #Patch Set 6 : Refactor timers and add tests; add document-level aggregation. #
Total comments: 10
Patch Set 7 : Use product name instead of project name. #
Total comments: 12
Patch Set 8 : Address various comments. #
Total comments: 13
Patch Set 9 : Address more comments, rename histograms #
Total comments: 2
Patch Set 10 : Change measurement unit. #Messages
Total messages: 52 (25 generated)
Balazs, please take a first look.
pkalinnikov@chromium.org changed reviewers: + engedy@chromium.org
https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:11: Add include guards.
LGTM % comments. Thanks! https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:1: // Copyright 2016 The Chromium Authors. All rights reserved. Could you please run this entire file by rkaplow@ and get his thoughts on it? https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:5: // This file provides macros for reporting TimeTicks/ThreadTicks with nit: s/reporting/recording https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:17: // Scoped class which logs its time on this thread, measured in milliseconds, as How about: ... which records how long the current thread has been doing actual work during the lifetime of the instance, measured ... https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:26: // pointer created, followed by a RAII object referring to that histogram, and nit: What is the resource that is being acquired here for the lifetime of the instance? https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:39: // Same as SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h", but nit: Similar to ... https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:40: // measures time in microseconds, up to 100 milliseconds. Recommended for 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. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:45: // Same as SCOPED_UMA_HISTOGRAM_THREAD_TIMER, but measures time in microseconds, Similar to SCOPED_UMA_HISTOGRAM_THREAD_TIMER above, ... https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:47: // precision, free of time spent for blocking operations. nit: spent on https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:84: using ThreadTicksProvider = base::ThreadTicks; ThreadTicks seems to have WaitUntilInitialized(), which we probably need to call in the ctor. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:86: template <typename TimeProvider, bool is_micro> nit: s/is_micro/is_microsec_precision/ https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:105: using TimeType = decltype(TimeProvider::Now()); nit: Blank line after. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:108: }; nit: DISALLOW_COPY_AND_ASSIGN, and #include "base/macros.h" https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62295: + Records how much time it takes to decide whether subresource filtering nit: how long it takes https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62366: + The total time it took to obtain and index all rules. Does not include time Phrasing suggestion: The total CPU time it took to (parse|read) and index all rules. Does not include time when the indexing thread was not doing actual work, e.g. waiting for I/O or being descheduled. Recorded every time the RulesetService kicks off a ruleset indexing process. https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62414: + records the thread CPU time spent for providing the allowLoad decision. nit: spent on calculating. (same below)
Thanks Balazs. Addressed all comments, except the one asking to add time measurements in the comments. I will do this a bit later. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:1: // Copyright 2016 The Chromium Authors. All rights reserved. On 2016/11/16 14:48:07, engedy wrote: > Could you please run this entire file by rkaplow@ and get his thoughts on it? Will add him as a reviewer. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:5: // This file provides macros for reporting TimeTicks/ThreadTicks with On 2016/11/16 14:48:07, engedy wrote: > nit: s/reporting/recording Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:11: On 2016/11/16 13:53:48, pkalinnikov wrote: > Add include guards. Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:17: // Scoped class which logs its time on this thread, measured in milliseconds, as On 2016/11/16 14:48:07, engedy wrote: > How about: > > ... which records how long the current thread has been doing actual work during > the lifetime of the instance, measured ... Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:26: // pointer created, followed by a RAII object referring to that histogram, and On 2016/11/16 14:48:07, engedy wrote: > nit: What is the resource that is being acquired here for the lifetime of the > instance? The resource is logical rather than physical. Resource = the launched timer, awaiting to be finished. Does "scoped" sound better? https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:39: // Same as SCOPED_UMA_HISTOGRAM_TIMER in "base/metrics/histogram_macros.h", but On 2016/11/16 14:48:07, engedy wrote: > nit: Similar to ... Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:45: // Same as SCOPED_UMA_HISTOGRAM_THREAD_TIMER, but measures time in microseconds, On 2016/11/16 14:48:07, engedy wrote: > Similar to SCOPED_UMA_HISTOGRAM_THREAD_TIMER above, ... Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:47: // precision, free of time spent for blocking operations. On 2016/11/16 14:48:07, engedy wrote: > nit: spent on Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:84: using ThreadTicksProvider = base::ThreadTicks; On 2016/11/16 14:48:07, engedy wrote: > ThreadTicks seems to have WaitUntilInitialized(), which we probably need to call > in the ctor. Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:86: template <typename TimeProvider, bool is_micro> On 2016/11/16 14:48:07, engedy wrote: > nit: s/is_micro/is_microsec_precision/ Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:105: using TimeType = decltype(TimeProvider::Now()); On 2016/11/16 14:48:07, engedy wrote: > nit: Blank line after. Done. https://codereview.chromium.org/2503283003/diff/1/components/subresource_filt... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:108: }; On 2016/11/16 14:48:07, engedy wrote: > nit: DISALLOW_COPY_AND_ASSIGN, and #include "base/macros.h" Done. https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62295: + Records how much time it takes to decide whether subresource filtering On 2016/11/16 14:48:08, engedy wrote: > nit: how long it takes Done. https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62366: + The total time it took to obtain and index all rules. Does not include time On 2016/11/16 14:48:07, engedy wrote: > Phrasing suggestion: > > The total CPU time it took to (parse|read) and index all rules. Does not include > time when the indexing thread was not doing actual work, e.g. waiting for I/O or > being descheduled. Recorded every time the RulesetService kicks off a ruleset > indexing process. Done. https://codereview.chromium.org/2503283003/diff/1/tools/metrics/histograms/hi... tools/metrics/histograms/histograms.xml:62414: + records the thread CPU time spent for providing the allowLoad decision. On 2016/11/16 14:48:08, engedy wrote: > nit: spent on calculating. (same below) Done.
pkalinnikov@chromium.org changed reviewers: + rkaplow@chromium.org
Hi Robert, Can you please review the "scoped_uma_histogram_timers.h" file? Macros thereof are used in the reset of the touched files.
Description was changed from ========== Add high-precision timing histograms. BUG=609747 ========== to ========== Add high-precision timing histograms. BUG=609747 ==========
rkaplow@chromium.org changed reviewers: + isherman@chromium.org - rkaplow@chromium.org
rkaplow@chromium.org changed reviewers: + rkaplow@chromium.org
will let ilya review since he's been looking into this on the thread
https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:33: // See: "base/metrics/histogram_macros_internal.h". Please document that names passed to the macro must be runtime constants. https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:55: __COUNTER__) nit: I'd probably group the two THREAD_TIMERs together https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:55: __COUNTER__) 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? https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:76: name, 1, is_micro ? 100000 : 10000, 50, \ I guess that constant propagation probably makes the is_micro ternary statement actually just be a constant load? https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:77: base::HistogramBase::kUmaTargetedHistogramFlag); \ 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? https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62283: + units="us"> nit: s/us/microseconds (and if you wouldn't mind, it would be great to update tools/metrics/histograms/pretty_print.py with that preference -- possibly in a separate CL if there are existing violations) https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62292: + units="ms"> Why are the two types of histograms using different units? I'd expect the times to be pretty similar, no?
https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:33: // See: "base/metrics/histogram_macros_internal.h". On 2016/11/18 22:26:05, Ilya Sherman wrote: > Please document that names passed to the macro must be runtime constants. Done. https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:55: __COUNTER__) On 2016/11/18 22:26:05, Ilya Sherman wrote: > nit: I'd probably group the two THREAD_TIMERs together Done. https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:55: __COUNTER__) On 2016/11/18 22:26:05, Ilya Sherman wrote: > 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? 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? https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:76: name, 1, is_micro ? 100000 : 10000, 50, \ On 2016/11/18 22:26:05, Ilya Sherman wrote: > I guess that constant propagation probably makes the is_micro ternary statement > actually just be a constant load? Yes, I guess it should be optimized down to a constant. https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:77: base::HistogramBase::kUmaTargetedHistogramFlag); \ On 2016/11/18 22:26:05, Ilya Sherman wrote: > 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? 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... https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62283: + units="us"> On 2016/11/18 22:26:05, Ilya Sherman wrote: > nit: s/us/microseconds (and if you wouldn't mind, it would be great to update > tools/metrics/histograms/pretty_print.py with that preference -- possibly in a > separate CL if there are existing violations) Done. I didn't find any histogram in "histograms.xml" that would measure in microseconds, but wouldn't have "microseconds" as its unit. Since I use "microseconds" too, does it make sense to update the pretty_print.py script? https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62292: + units="ms"> On 2016/11/18 22:26:05, Ilya Sherman wrote: > Why are the two types of histograms using different units? I'd expect the times > to be pretty similar, no? My bad. Fixed.
Hi Ilya, Thanks for your comments. Please let me know if it now looks good.
Thanks! I think the thread-safety is okay, though I'd be more comfortable if someone very familiar with thread-safety guarantees were to review this code as well. https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:77: base::HistogramBase::kUmaTargetedHistogramFlag); \ On 2016/11/21 14:51:00, pkalinnikov wrote: > On 2016/11/18 22:26:05, Ilya Sherman wrote: > > 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? > > 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... > . 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. > 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. 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? > 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... https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62283: + units="us"> On 2016/11/21 14:51:00, pkalinnikov wrote: > On 2016/11/18 22:26:05, Ilya Sherman wrote: > > nit: s/us/microseconds (and if you wouldn't mind, it would be great to update > > tools/metrics/histograms/pretty_print.py with that preference -- possibly in a > > separate CL if there are existing violations) > > Done. I didn't find any histogram in "histograms.xml" that would measure in > microseconds, but wouldn't have "microseconds" as its unit. Since I use > "microseconds" too, does it make sense to update the pretty_print.py script? Yes, please go ahead and update https://cs.chromium.org/chromium/src/tools/metrics/histograms/pretty_print.py... in that case.
Hi Ilia, and thanks again. See commends, I have explicitly marked the code as not thread-safe. Do you still need somebody to review the thread-safety part? https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... File components/subresource_filter/core/common/scoped_uma_histogram_timers.h (right): https://codereview.chromium.org/2503283003/diff/20001/components/subresource_... components/subresource_filter/core/common/scoped_uma_histogram_timers.h:77: base::HistogramBase::kUmaTargetedHistogramFlag); \ On 2016/11/22 00:02:47, Ilya Sherman wrote: > On 2016/11/21 14:51:00, pkalinnikov wrote: > > On 2016/11/18 22:26:05, Ilya Sherman wrote: > > > 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? > > > > 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... > > . > > 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. 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. > > > 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. > > 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? 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). > > > 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... > https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:62283: + units="us"> On 2016/11/22 00:02:47, Ilya Sherman wrote: > On 2016/11/21 14:51:00, pkalinnikov wrote: > > On 2016/11/18 22:26:05, Ilya Sherman wrote: > > > nit: s/us/microseconds (and if you wouldn't mind, it would be great to > update > > > tools/metrics/histograms/pretty_print.py with that preference -- possibly in > a > > > separate CL if there are existing violations) > > > > Done. I didn't find any histogram in "histograms.xml" that would measure in > > microseconds, but wouldn't have "microseconds" as its unit. Since I use > > "microseconds" too, does it make sense to update the pretty_print.py script? > > Yes, please go ahead and update > https://cs.chromium.org/chromium/src/tools/metrics/histograms/pretty_print.py... > in that case. Updated the script. Please take a look.
> Hi Ilia, and thanks again. I mean Ilya, sorry.
The CQ bit was checked by pkalinnikov@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...
Hey Balazs and Ilya, Please take another look. I decoupled time reporting from the scoped object to allow for custom reporting mechanisms, e.g., accumulating TimeDelta locally before sending to a histogram.
https://codereview.chromium.org/2503283003/diff/120001/components/subresource... File components/subresource_filter/core/common/scoped_timers_unittest.cc (right): https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers_unittest.cc:85: SCOPED_UMA_HISTOGRAM_MICRO_TIMER("ScopedTimers.MicroTimer"); Should I do something to suppress the following warning? ** Presubmit Warnings ** Some UMA_HISTOGRAM lines have been modified and the associated histogram name has no match in either tools/metrics/histograms/histograms.xml or the modifications of it: [components/subresource_filter/core/common/scoped_timers_unittest.cc:83] ScopedTimers.ThreadTimer \ [components/subresource_filter/core/common/scoped_timers_unittest.cc:84] ScopedTimers.MicroThreadTimer \ [components/subresource_filter/core/common/scoped_timers_unittest.cc:85] ScopedTimers.MicroTimer \ [components/subresource_filter/core/common/scoped_timers_unittest.cc:100] ScopedTimers.MicroTimes
Still LGTM % comments. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/content/renderer/document_subresource_filter.h (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/document_subresource_filter.h:44: // Time aggregates for all allowLoad calls. nit: I'd suggest wording this slightly differently so that it is clear what aggregation means in this context, i.e. it is the total time spent in allowLoad() calls while evaluating subresource loads. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/document_subresource_filter.h:45: base::TimeDelta total_wall_duration; nit: How about |evaluation_total_wall_duration|? Same below. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/content/renderer/subresource_filter_agent.cc (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:96: UMA_HISTOGRAM_TIMES( What do you think about recording MICRO_TIMES here as well? https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:26: // Creates a scoped object that measures its lifetime using base::TimeTicks, and Have you considered making this no longer a macro, but directly exposing type alias templates ScopedTimer<Fun> and ScopedThreadTimer<Fun>, or factory functions? https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/core/common/scoped_timers_unittest.cc (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/core/common/scoped_timers_unittest.cc:29: SCOPED_TIMER(std::ref(export_functor)); nit: std::ref is not currently allowed by the Chromium C++11 style guide.
Thanks for following up on the thread-safety concern! It's a bit hard for me to see what changed in the scoped_timers.h code -- did you simply add a SCOPED_TIMER macro, or did you also change the histogram-reporting macros around? https://codereview.chromium.org/2503283003/diff/120001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:7: // with base::TimeTicks and base::ThreadTicks. Please explicitly mention the lack of thread-safety https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:13: // after some refactoring. Please explicitly mention the lack of thread-safety in this TODO (yes, in addition to mentioning it above -- it's important to mention it above for any users of this file, and it's important to mention here for anyone thinking about doing the refactoring). https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:34: // SCOPED_TIMER(export_time); Does this actually need to be a macro? If so, why? https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:69: // WARN: The generated code is not thread-safe. nit: s/WARN/WARNING or NOTE or CAUTION https://codereview.chromium.org/2503283003/diff/120001/tools/metrics/histogra... File tools/metrics/histograms/pretty_print.py (right): https://codereview.chromium.org/2503283003/diff/120001/tools/metrics/histogra... tools/metrics/histograms/pretty_print.py:35: 'microsecond': 'microseconds', Please also list "'us': 'microseconds'"
The CQ bit was checked by pkalinnikov@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: chromeos_daisy_chromium_compile_only_ng on master.tryserver.chromium.linux (JOB_FAILED, http://build.chromium.org/p/tryserver.chromium.linux/builders/chromeos_daisy_...)
The CQ bit was checked by pkalinnikov@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...
Hi Ilya and Balazs, Thanks for your comments. isherman@: I added SCOPED_*TIMER macros and also factored out UMA histogram reporting into ExportTimeDeltaToHistogram class. Factoring out is needed because we are interested in custom TimeDelta handlers, e.g. in "subresource_filter_agent.cc" file where we both report measurement to a histogram and accumulate total time in a variable. This refactoring also caused me to change macros around. It might be indeed hard to track differences between patches, maybe reviewing the whole thing at once would be better. engedy@: Please take another look. In particular, what do you think about time ranges that I chose? https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/content/renderer/document_subresource_filter.h (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/document_subresource_filter.h:44: // Time aggregates for all allowLoad calls. On 2016/11/28 14:29:26, engedy wrote: > nit: I'd suggest wording this slightly differently so that it is clear what > aggregation means in this context, i.e. it is the total time spent in > allowLoad() calls while evaluating subresource loads. Done. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/document_subresource_filter.h:45: base::TimeDelta total_wall_duration; On 2016/11/28 14:29:26, engedy wrote: > nit: How about |evaluation_total_wall_duration|? Same below. Done. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/content/renderer/subresource_filter_agent.cc (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:96: UMA_HISTOGRAM_TIMES( On 2016/11/28 14:29:26, engedy wrote: > What do you think about recording MICRO_TIMES here as well? Done. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:26: // Creates a scoped object that measures its lifetime using base::TimeTicks, and On 2016/11/28 14:29:26, engedy wrote: > Have you considered making this no longer a macro, but directly exposing type > alias templates ScopedTimer<Fun> and ScopedThreadTimer<Fun>, or factory > functions? As discussed offline: - Alias templates are too wordy (for lambdas, e.g., they would require to write decltype in the template parameter list). - Factory functions would return ScopedTimer objects by value. If put RVO aside, ctor/dtor could be called more than once. We don't want to rely on RVO. https://codereview.chromium.org/2503283003/diff/100001/components/subresource... File components/subresource_filter/core/common/scoped_timers_unittest.cc (right): https://codereview.chromium.org/2503283003/diff/100001/components/subresource... components/subresource_filter/core/common/scoped_timers_unittest.cc:29: SCOPED_TIMER(std::ref(export_functor)); On 2016/11/28 14:29:26, engedy wrote: > nit: std::ref is not currently allowed by the Chromium C++11 style guide. How about this? https://codereview.chromium.org/2503283003/diff/120001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:7: // with base::TimeTicks and base::ThreadTicks. On 2016/11/29 03:02:48, Ilya Sherman wrote: > Please explicitly mention the lack of thread-safety Done. https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:13: // after some refactoring. On 2016/11/29 03:02:48, Ilya Sherman wrote: > Please explicitly mention the lack of thread-safety in this TODO (yes, in > addition to mentioning it above -- it's important to mention it above for any > users of this file, and it's important to mention here for anyone thinking about > doing the refactoring). Done. https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:34: // SCOPED_TIMER(export_time); On 2016/11/29 03:02:48, Ilya Sherman wrote: > Does this actually need to be a macro? If so, why? Two reasons: 1. To have the same style as other SCOPED_* macros. 2. To be less wordy. Compare: - SCOPED_TIMER(functor); vs. ScopedTimer<FunctorType> scoped_timer(functor); - SCOPED_TIMER(stored_lambda); vs. ScopedTimer<decltype(stored_lambda)> scoped_timer(stored_lambda); Otherwise, I don't have stronger arguments towards macro. What do you think? https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:69: // WARN: The generated code is not thread-safe. On 2016/11/29 03:02:48, Ilya Sherman wrote: > nit: s/WARN/WARNING or NOTE or CAUTION Done. https://codereview.chromium.org/2503283003/diff/120001/tools/metrics/histogra... File tools/metrics/histograms/pretty_print.py (right): https://codereview.chromium.org/2503283003/diff/120001/tools/metrics/histogra... tools/metrics/histograms/pretty_print.py:35: 'microsecond': 'microseconds', On 2016/11/29 03:02:48, Ilya Sherman wrote: > Please also list "'us': 'microseconds'" Done.
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: Try jobs failed on following builders: ios-simulator on master.tryserver.chromium.mac (JOB_FAILED, http://build.chromium.org/p/tryserver.chromium.mac/builders/ios-simulator/bui...)
LGTM % comments. Ranges look good. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/content/renderer/subresource_filter_agent.cc (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:97: UMA_HISTOGRAM_CUSTOM_MICRO_TIMES( Please update unittests to verify that samples for these histograms are recorded too. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:98: "SubresourceFilter.DocumentLoad.SubresourceSums.Evaluation.WallDuration", On second read, these histogram names sound a bit awkward, but I'm not sure. What do you think about: SubresourceFilter.DocumentLoad.SubresourceEvaluation.TotalWallDuration Better, worse? https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:153: // WARNING: Static local variable initialization is deliberately *not* nit: To provide context, point to the BUILD file where this is specified. https://codereview.chromium.org/2503283003/diff/140001/tools/metrics/histogra... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/140001/tools/metrics/histogra... tools/metrics/histograms/histograms.xml:63247: + records the thread CPU time spent on calculating. nit: ... calculating whether it should be allowed to load. (Same below.)
This CL honestly adds a lot more macro and template magic than I'd prefer. However, to the best of my understanding, it seems to be a safe way to record UMA metrics, given the explicit comments about the lack of thread safety. Since I'm not an owner for the macro code itself, I defer to those who are =) So, metrics aspects of this CL LGTM. https://codereview.chromium.org/2503283003/diff/120001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/120001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:34: // SCOPED_TIMER(export_time); On 2016/11/30 10:13:47, pkalinnikov wrote: > On 2016/11/29 03:02:48, Ilya Sherman wrote: > > Does this actually need to be a macro? If so, why? > > Two reasons: > 1. To have the same style as other SCOPED_* macros. > 2. To be less wordy. Compare: > - SCOPED_TIMER(functor); vs. ScopedTimer<FunctorType> scoped_timer(functor); > - SCOPED_TIMER(stored_lambda); vs. ScopedTimer<decltype(stored_lambda)> > scoped_timer(stored_lambda); > > Otherwise, I don't have stronger arguments towards macro. What do you think? Could you define a ScopedTimer class that runs a base::Callback that accepts a TimeDelta? (Or maybe there's an equivalent way to phrase that with lambda functions? Basically, I'm not sure why a template would need to be involved.) https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/content/renderer/subresource_filter_agent.cc (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:98: "SubresourceFilter.DocumentLoad.SubresourceSums.Evaluation.WallDuration", On 2016/11/30 12:42:28, engedy wrote: > On second read, these histogram names sound a bit awkward, but I'm not sure. > What do you think about: > > SubresourceFilter.DocumentLoad.SubresourceEvaluation.TotalWallDuration > > Better, worse? +1 https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:92: name, impl::TimeTicksProvider, impl::ExportTimeDeltaToHistogram<true>, \ Optional: I find it really confusing to read true vs. false here -- the labels don't mean anything until I go read the definition below. It would be nice to phrase this in a way that avoids this issue. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:93: 1000000, __COUNTER__) Optional nit: I think "1000 * 1000" is easier to parse than "1000000"; ditto for "10 * 1000" vs. "10000".
Hello and thanks again for your comments. isherman@: Indeed the amount of magic is big, but hopefully it'll be decreased in the follow-up CLs that I prepare. I addressed your comments, but apart from them you don't need to review the CL further. engedy@: Balazs, please take one more look. Do you think it makes sense to add some phrase to histograms.xml saying that CPU time is reported only if ThreadTicks is supported? In the follow-up CL we'll stop reporting both wall and CPU measurements in this case, so such a comment will no longer be needed. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/content/renderer/subresource_filter_agent.cc (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:97: UMA_HISTOGRAM_CUSTOM_MICRO_TIMES( On 2016/11/30 12:42:28, engedy wrote: > Please update unittests to verify that samples for these histograms are recorded > too. Done. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/content/renderer/subresource_filter_agent.cc:98: "SubresourceFilter.DocumentLoad.SubresourceSums.Evaluation.WallDuration", On 2016/11/30 12:42:28, engedy wrote: > On second read, these histogram names sound a bit awkward, but I'm not sure. > What do you think about: > > SubresourceFilter.DocumentLoad.SubresourceEvaluation.TotalWallDuration > > Better, worse? Done here and in histograms.xml. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... File components/subresource_filter/core/common/scoped_timers.h (right): https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:92: name, impl::TimeTicksProvider, impl::ExportTimeDeltaToHistogram<true>, \ On 2016/12/01 05:39:07, Ilya Sherman wrote: > Optional: I find it really confusing to read true vs. false here -- the labels > don't mean anything until I go read the definition below. It would be nice to > phrase this in a way that avoids this issue. Done. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:93: 1000000, __COUNTER__) On 2016/12/01 05:39:08, Ilya Sherman wrote: > Optional nit: I think "1000 * 1000" is easier to parse than "1000000"; ditto for > "10 * 1000" vs. "10000". Done. https://codereview.chromium.org/2503283003/diff/140001/components/subresource... components/subresource_filter/core/common/scoped_timers.h:153: // WARNING: Static local variable initialization is deliberately *not* On 2016/11/30 12:42:28, engedy wrote: > nit: To provide context, point to the BUILD file where this is specified. Done. https://codereview.chromium.org/2503283003/diff/140001/tools/metrics/histogra... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/140001/tools/metrics/histogra... tools/metrics/histograms/histograms.xml:63247: + records the thread CPU time spent on calculating. On 2016/11/30 12:42:28, engedy wrote: > nit: ... calculating whether it should be allowed to load. (Same below.) Done.
LGTM % nit, thanks! Histogram desciptions are perfectly fine, let's not change them for a day. https://codereview.chromium.org/2503283003/diff/160001/tools/metrics/histogra... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/160001/tools/metrics/histogra... tools/metrics/histograms/histograms.xml:63612: + units="ms"> nit: This and the one below should be "microseconds".
The CQ bit was checked by pkalinnikov@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...
pkalinnikov@chromium.org changed reviewers: - rkaplow@chromium.org
Changed unit of measurement. https://codereview.chromium.org/2503283003/diff/160001/tools/metrics/histogra... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2503283003/diff/160001/tools/metrics/histogra... tools/metrics/histograms/histograms.xml:63612: + units="ms"> On 2016/12/01 18:20:46, engedy wrote: > nit: This and the one below should be "microseconds". Done.
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
(Still LGTM, thanks)
The CQ bit was checked by pkalinnikov@chromium.org
The patchset sent to the CQ was uploaded after l-g-t-m from engedy@chromium.org Link to the patchset: https://codereview.chromium.org/2503283003/#ps180001 (title: "Change measurement unit.")
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": 180001, "attempt_start_ts": 1480669153099150,
"parent_rev": "c4bbd41dcbf836ec1035c6338e2d8eff320356a3", "commit_rev":
"11fa17e25f1a43eb3adf552b6f5ba6e0f7699f4d"}
Message was sent while issue was closed.
Description was changed from ========== Add high-precision timing histograms. BUG=609747 ========== to ========== Add high-precision timing histograms. BUG=609747 ==========
Message was sent while issue was closed.
Committed patchset #10 (id:180001)
Message was sent while issue was closed.
Description was changed from ========== Add high-precision timing histograms. BUG=609747 ========== to ========== Add high-precision timing histograms. BUG=609747 Committed: https://crrev.com/7c84dd6c2273cea47031237046ec001ac7fb75ea Cr-Commit-Position: refs/heads/master@{#435890} ==========
Message was sent while issue was closed.
Patchset 10 (id:??) landed as https://crrev.com/7c84dd6c2273cea47031237046ec001ac7fb75ea Cr-Commit-Position: refs/heads/master@{#435890} |
