New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 777568 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Nov 2017
Cc:
Components:
EstimatedDays: ----
NextAction: 2017-11-27
OS: Mac
Pri: 3
Type: Bug



Sign in to add a comment

NewTabPage.LoadTime has a lot of samples (3%) in 0-1ms bucket

Project Member Reported by asvitk...@chromium.org, Oct 23 2017

Issue description

NewTabPage.LoadTime has a lot of samples (3%) in 0-1ms bucket on Mac.

This metric is currently listed as a heartbeat metric that Chirp alerts on.

It seems suspicious to me that we can actually load the new tab page in under 1ms, so I wonder if there's an error with the measurement code. If there isn't an error and this value is legitimate, we should make the metric description explain this case - as it otherwise looks very surprising.

https://uma.googleplex.com/p/chrome/histograms?endDate=20171022&dayCount=7&histograms=NewTabPage.LoadTime&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Cchannel%2Ceq%2C4%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

Not sure who should own this - the Mac team or the NTP team. So leaving unassigned and cc'ing shrike@ (Mac TL) and treib@ (metric owner).

Also cc'ing speed releasing folks.


 

Comment 1 by shrike@chromium.org, Oct 23 2017

Cc: treib@chromium.org
+treib@

Looking through the code, I can't actually find where NTPUserDataLogger::LogEvent(NTP_ALL_TILES_LOADED, load_time) gets called.

Comment 2 by treib@chromium.org, Oct 24 2017

The metric also has samples in the 0-1ms bucket on other platforms (though not as many), so I don't think this is completely Mac-specific.

The call originates from here:
https://cs.chromium.org/chromium/src/chrome/browser/resources/local_ntp/most_visited_single.js?rcl=b5bd67a6d1f77ba662eb7f9ed42de0a631fc5b54&l=167
(and takes quite a long path before it arrives at NTPUserDataLogger, including special JS bindings and Mojo IPC.)

Interestingly, there's a DCHECK verifying that the time isn't negative:
https://cs.chromium.org/chromium/src/chrome/renderer/searchbox/searchbox.cc?rcl=9e0190d23863adcf5851a7741e9b73fae4aced0c&l=238
Components: UI>Browser>NewTabPage
Status: Available (was: Untriaged)
Labels: zine-triaged

Comment 5 by treib@chromium.org, Nov 14 2017

Owner: treib@chromium.org
Status: Assigned (was: Available)
I'll take a look. My first guess is that the "start" and "end" times come from different sources which can be out of sync.
The "start" time comes from render_frame()->GetWebFrame()->Performance().NavigationStart() (have to figure out how exactly that is populated), while the "end" time is base::TimeTicks::Now().
https://cs.chromium.org/chromium/src/chrome/renderer/searchbox/searchbox.cc?rcl=7d42428d0212aa3a337168c95e0f4d0a6cd2e974&l=234

Comment 6 by treib@chromium.org, Nov 17 2017

Status: Started (was: Assigned)
Navigation timing is weird and complicated...

Potential problem: SearchBox::LogEvent essentially ends up computing a delta between a base::Time and a base::TimeTicks, both converted to "ms since epoch" format. It gets the current time from TimeTicks::Now(), but the navigation start time from WebPerformance::NavigationStart() which is a wall time (in a convoluted way). That's fishy as hell, but I *think* it's not really any worse than just computing a delta between base::Times. Anyway, let's fix that and see what happens.
Project Member

Comment 7 by bugdroid1@chromium.org, Nov 20 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/193879ecdb90ce7e6cc738482b850202abafedaf

commit 193879ecdb90ce7e6cc738482b850202abafedaf
Author: Marc Treib <treib@chromium.org>
Date: Mon Nov 20 18:34:40 2017

Clean up time computation in SearchBox::LogEvent

LogEvent computes the time between the current event and navigation
start. It gets the navigation start time from WebPerformance::
NavigationStart() which is a wall time (i.e. base::Time), but before
this CL, it got the current time from base::TimeTicks::Now(). This CL
fixes that by using base::Time::Now() instead and also cleans up the
code a bit.

I believe this is a pure cleanup, though I'm not entirely sure if the
old way always delivered well-defined results.

Bug:  777568 
Change-Id: I81ed3e1fae2650a6bbc053ae8a4917a8e6c91f5e
Reviewed-on: https://chromium-review.googlesource.com/776854
Commit-Queue: Marc Treib <treib@chromium.org>
Reviewed-by: Mikel Astiz <mastiz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#517866}
[modify] https://crrev.com/193879ecdb90ce7e6cc738482b850202abafedaf/chrome/renderer/searchbox/searchbox.cc

Comment 8 by treib@chromium.org, Nov 22 2017

NextAction: 2017-11-27
Huh, it looks like the above CL actually fixed this: 64.0.3274.0 is the first version that contains that CL, and in this version the 0 samples are gone:
https://uma.googleplex.com/p/chrome/histograms/?endDate=20171121&dayCount=1&histograms=NewTabPage.LoadTime&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Csimple_version%2Ccnt%2C64.0.3274.%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

While in the previous version 3273 they're still there:
https://uma.googleplex.com/p/chrome/histograms/?endDate=20171121&dayCount=1&histograms=NewTabPage.LoadTime&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Csimple_version%2Ccnt%2C64.0.3273.%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

Let's watch it for a few more days, but I think this is fixed. It'll be interesting to see if median, 90th percentile etc are affected by this at all.
Sweet! Thanks for fixing.
The NextAction date has arrived: 2017-11-27

Sign in to add a comment