Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

FMP metrics: Don't require tracingStartedInPage to precede navStart #1152

Merged
merged 6 commits into from
Dec 14, 2016

Conversation

paulirish
Copy link
Member

The short version is: sometimes traces have the tracingStartedInPage event following after the navigationStart. We use the former to find our renderer thread of interest. The navStart is the time origin for all our metrics.

This PR changes the logic to align with traceviewer's approach: look at navStarts that precede events of interest.

This PR also adds two new tests:

  1. a trace of chrome://history which was reported by a user as failing to deliver metrics
  2. the bad-nav-start-ts.json which was asserted to return a -1, but actually should be working. So now we deliver real values.

Fixes #753

Some examples:

gmail:
image

chrome://history:
image

devtools.chrome.com
image

const firstContentfulPaint = (evts.firstContentfulPaint.ts - evts.navigationStart.ts) / 1000;

const timings = {};
timings.navStart = evts.navigationStart.ts / 1000;
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this was pre-existing, but seems a little odd that the the first*Paint are durations/diffs while the navStart is a timestamp. I guess it makes sense since the point is the navStart diff is 0. Is this inconsistency well understood?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is fair. Originally I was thinking of something like:

{ 
  timestamps: {
    navStart: 8923942942.122,
    fCP: 8934942942.246,
    FMP: 8926942942.572
  },
  timings: {
    navStart: 0,
    fCP: 1201.33,
    FMP: 1642.55
  }
}

Happy to update it to this format. And in fact, there are downstream consumers of the timestamps, so I'm happy to keep those around.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1 to moving to that, a lot clearer what the values should look like there

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done.

const firstMeaningfulPaint = (data.fMP.ts - data.navStart.ts) / 1000;
static calculateScore(evts) {
const firstMeaningfulPaint = (evts.firstMeaningfulPaint.ts - evts.navigationStart.ts) / 1000;
const firstContentfulPaint = (evts.firstContentfulPaint.ts - evts.navigationStart.ts) / 1000;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just checking...I've seen multiple FCP events in a trace. https://bugs.chromium.org/p/chromium/issues/detail?id=673922. Will this need to be more robust to handle those cases?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it should handle that. The audit is only looking at the first fCP that has the same frameID as the first tracingStartedInPage.

The traces in fixtures have multiple fCP's per trace already. :)

// Filter to just events matching the frame ID for sanity
const events = eventsAllFrames.filter(e => e.args.frame === startedInPageEvt.args.data.page);

// Find our first FCP. Our navStart will be the latest one before fCP.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Move "Our navStart will be the latest one before fCP." comment before its line.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

done

const navigationStart = events.filter(e =>
e.name === 'navigationStart' && e.ts < firstFCP.ts).pop();
// FMP will follow at/after the FCP
const firstMeaningfulPaint = events.find(e =>
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

despite the multiple finds, this is a lot cleaner than before. 👍


// Process the trace
const tracingProcessor = new TracingProcessor();
const trace = artifacts.traces[Audit.DEFAULT_PASS];
const model = tracingProcessor.init(trace);
const endOfTraceTime = model.bounds.max;

// TODO: Wait for DOMContentLoadedEndEvent
const fMPts = timings.fMP + timings.navStart;
const fmpTiming = fmpResult.rawValue;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no more parseFloat?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good question. I'm gonna normalize all the exported rawValues to be parseFloat(num.toFixed(1)) so we never have to parseFloat randomly.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

did a pass with parsefloat/toFixed so we return numbers where they are expected:
562aee4

timestamps: {
fMP: fMPtsInMS * 1000,
visuallyReady: (visuallyReadyTiming + navStartTsInMS) * 1000,
mainThreadAvail: (timeToInteractive + navStartTsInMS) * 1000
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason to call this mainTreadAvail instead of timeToInteractive?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right now, no. We may introduce more signals to TTI that would necessitate differentiating the two but I'm okay with this rename.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

renamed.

@@ -53,8 +53,8 @@ describe('Performance: time-to-interactive audit', () => {
assert.equal(output.rawValue, '1105.8', output.debugString);
assert.equal(output.extendedInfo.value.expectedLatencyAtTTI, '20.72');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shall we just make all of these floats?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

k done

Copy link
Member

@brendankenny brendankenny left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM2. Great changes -- more robust and easier to follow code :)

@brendankenny brendankenny merged commit ea4561a into master Dec 14, 2016
@brendankenny brendankenny deleted the fmp-fix branch December 14, 2016 01:44
andrewrota pushed a commit to andrewrota/lighthouse that referenced this pull request Jan 13, 2017
…oogleChrome#1152)

* fix fmp calculation.

* add more tests for finding fmp in tricky cases.

* Expose timestamps and timings in the FMP extendedInfo.

* add timestamps to TTI as well.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants