NavigationThrottle tracing has off-by-one error |
||||
Issue descriptionThe "navigation" category has wonderful tracing. However, I noticed some strange behavior today when I saw a trace from MetricsNavigationThrottle::WillRedirectRequest taking 3ms. That class does not override WillRedirectRequest so an empty method should not take 3ms. Then I took a look at the code and it appears we start the trace for thottle [i] *after* throttle [i] computes its result. This means that the trace for throttle [i] is really timing the computation of throttle [i+1] (afaict). There is a bit of complication because the trace wants to log the result of the computation, but maybe it is doable.
,
Dec 7 2017
The tracing in NavigationHandle throttle execution is meant to record the responses for debugging purposes, which is why it is an explicit TRACE_EVENT_ASYNC_STEP_INTO. It just traces the stages through which we go in NavigationHandle. It was not meant to be a measurement tool, so there is no start/end tracing pair.
,
Dec 7 2017
Ah I see. This confused kinuko and me. I think ideally we could have both. In the meantime, since there are use cases for measuring sync throttle duration, I was planning on just logging standard TRACE_EVENTs for those. If we ever get e.g. TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP* macros (!), we could remove the TRACE_EVENT ones.
,
Dec 7 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/7d4ed459a193069b1fc1669377e0dc7eba4e27bc commit 7d4ed459a193069b1fc1669377e0dc7eba4e27bc Author: Charles Harrison <csharrison@chromium.org> Date: Thu Dec 07 15:29:31 2017 Add trace for synchronous time spent in WillStartRequest I've noticed that these can be a bit slow, but the async traces make analysis pretty confusing, due to the linked bug. Bug: 783327 Change-Id: I4d46d715d08ed176bec85b0672b24aab2e2b0022 Reviewed-on: https://chromium-review.googlesource.com/810927 Reviewed-by: Nasko Oskov <nasko@chromium.org> Commit-Queue: Charlie Harrison <csharrison@chromium.org> Cr-Commit-Position: refs/heads/master@{#522433} [modify] https://crrev.com/7d4ed459a193069b1fc1669377e0dc7eba4e27bc/content/browser/frame_host/navigation_handle_impl.cc
,
Dec 19 2017
csharrison@, do you think there is anything else you want to do on this bug? Possibly do the same for other Will* methods?
,
Dec 19 2017
Yeah I think that makes sense, WDYT? I am most concerned with navigation start since that represents the vast majority of cases (performance wise). Happy to do whichever you think is best, or just close this.
,
Dec 19 2017
I'd say let's add traces only for the things we really care about. If you think we don't immediately find useful to have timing specific traces for the other Will* events, I'm fine with just closing the bug. I just want to avoid having it linger open for a while with no traction.
,
Dec 19 2017
SGTM. I will mark as "fixed" in that case since my use case has been sated :D Can always re-open if we find the other methods are also causing confusion. |
||||
►
Sign in to add a comment |
||||
Comment 1 by csharrison@chromium.org
, Nov 9 2017