1531790 - With the Persist Logs option checked in the Network tab of the developer tools, the DOMContentLoaded and load metrics don't reset on page refreshes

Status: RESOLVED FIXED

(DevTools :: Netmonitor, defect, P3)

Description

[gj]

Attachment: Long page load time, or the longest page load time?

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:65.0) Gecko/20100101 Firefox/65.0

Steps to reproduce:

1. Open the Developer Tools on any page
2. Go to the Network tab
3. Check the Persist Logs option
4. Refresh the page several times, letting some time pass between refreshes

Actual results:

The DOMContentLoaded and load timers at the bottom of the Developer Tools continued tracking time from the first time I refreshed after checking the Persist Logs option.

Expected results:

I would have expected the two timers to reset on subsequent page refreshes, as is the behavior when the Persist Logs option is unchecked.

Comment 1

[Stefan [:StefanG_QA]]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:67.0) Gecko/20100101 Firefox/67.0 20190305092747

I've tested this report on OS X 10.13 using the latest Nightly and Firefox release build. I was able to reproduce the mentioned behavior. When following the steps the DOMContentLoaded and Load timers do not reset when refreshing the page.

Comment 2

[Hemakshi Sachdev [:hemakshis]]

Hi!

I can reproduce this bug and would like to take it up!

Hemakshi

Comment 3

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Done!

Comment 4

[Hemakshi Sachdev [:hemakshis]]

Hi

The solution that I propose to solve this is that here in the getDisplayedTimingMarker() function we are returning the value for DOMContentLoaded and load as the difference of the current marker value and the firstStartedMillis.

Now, since the firstStartedMillis value is not updated on reload with persist logs enabled we get the values from the time when the page was first reloaded.

So, if we can have a state as requestsStarted (or any name we agree upon) in the reducers/timing-markers.js which is initialized to the time when a reload is triggered with persist logs enabled and then we can use this value to calculate the DOMContentLoaded and load values.

Persist Logs Enabled -> On reload we call the clearTimingsMarker() which returns a new TimingMarker state and then we can use this value to display the proper timing marker values.

So changing the getDisplayedTimingMarker() function to return value - state.timingMarker.requestsStarted

and the state in reducers/timing-markers.js to ->

function TimingMarkers() {
  return {
    firstDocumentDOMContentLoadedTimestamp: -1,
    firstDocumentLoadTimestamp: -1,
    requestsStarted: Date.parse(new Date()),
  };
}

Comment 5

[Hemakshi Sachdev [:hemakshis]]

Attachment: Bug 1531790 - Reset DOMContentLoaded and load metrics on Reload while Persist Logs is enabled. r=Honza

Added a new state requestsStarted in the timing-marker.js reducer which is initialized with the time a new reload (when persist logs in enabled) is triggered. Used this parameter to calculate the DOMContentLoaded and load metrics in the StatusBar.

Comment 6

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Thanks for the analysis!

Some comments:

1. I think that you are looking at the right code and going in the right direction.

2. The main issue with the proposed solution is that we can't base the timing data on a time measured on the client side. I am referring to: requestsStarted: Date.parse(new Date()). The only valid timing is always the one coming from the backend.

Note that DevTools are based on client <-> server architecture where all measurements happens on the server (can be a mobile device, where the page is loaded) and data are sent to the client (the Toolbox and all the panels, including the Net panel) to be displayed to the user.

3. The selector really needs to be updated, but could we rather create a new state/field in the requests reducer? Something like: firstStartedMillisInTheLastReload (please come up with better name). This field would always be updated when reload happens - even if the persist log is on. Finally, this field would be used in the selector instead of firstStartedMillis. Or maybe we even need a new selector. Not sure whether we still need it (you need to do some analysis).

Honza

Comment 7

[Hemakshi Sachdev [:hemakshis]]

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #6)

3. The selector really needs to be updated, but could we rather create a new state/field in the requests reducer? Something like: firstStartedMillisInTheLastReload (please come up with better name). This field would always be updated when reload happens - even if the persist log is on. Finally, this field would be used in the selector instead of firstStartedMillis. Or maybe we even need a new selector. Not sure whether we still need it (you need to do some analysis).

I agree with having a new field which will be updated on each reload. Is there any way or some parameter with which we can know that the user has triggered a reload?

I was thinking that we can check if a particular request (We can take the first request (in the request list)) already exists in the requests array (by matching the URL). We can do this in the timing-marker.js selector itself. The new selector would look like -

const Services = require("Services");

function getDisplayedTimingMarker(state, marker) {
  const value = state.timingMarkers[marker];
  if (value == -1) {
    return value;
  }
  if (Services.prefs.getBoolPref("devtools.netmonitor.persistlog")) {
    const requests = [...state.requests.requests.values()];
    const firstRequestURL = requests[0].url;
    const matchingRequests = requests.filter(e => e.url === firstRequestURL);

    // This will always make sure that the latest request matching the first request URL is
    // used to take in the account of a reload.
    return value - matchingRequests[matchingRequests.length - 1].startedMillis;
  } else {
    return value - state.requests.firstStartedMillis;
  }
}

We can shift this method to the requests reducer as well and add a new field (firstStartedMillisAfterReload) as honza mentioned in the previous comment. In that case:-

The new addRequest reducer will call a function getFirstMillis (or any name we agree upon)
nextState.firstStartedMillisAfterReload = getFirstMillis(state.requests, newRequest);

And this function will look something like this->

function getFirstMillis(requestsMap, newRequest) {
  const requests = [...requestsMap.values()];

  // If `newRequest` is the first ever request return it's `startedMillis`
  if (requests.length === 0) {
    return newRequest.startedMillis;
  }

  const firstRequestURL = requests[0].url;
  const matchingRequests = requests.filter(e => e.url === firstRequestURL);

  // If true, means `newRequest` is the first request after a new reload
  if (newRequest.url === firstRequestURL) {
    matchingRequests.push(newRequest);
  }

  // This will always make sure that the latest request matching the first request URL is
  // used to take in the account of a reload
  return matchingRequests[matchingRequests.length - 1].startedMillis;
}

Comment 8

[Jan Honza Odvarko [:Honza] (always need-info? me)]

(In reply to Hemakshi Sachdev [:hemakshis] she/her from comment #7)

Thanks for quick update!

I was thinking that we can check if a particular request (We can take the first request (in the request list)) already exists in the requests array (by matching the URL). We can do this in the timing-marker.js selector itself. The new selector would look like

This feels unsafe see more below

I agree with having a new field which will be updated on each reload. Is there any way or some parameter with which we can know that the user has triggered a reload?

Some pointers:

1. Here is the place that resets the net panel content when the user reloads the page:
   https://searchfox.org/mozilla-central/rev/358f816f63da072145c593e9e2ac36b7250ecd25/devtools/client/netmonitor/src/connector/firefox-connector.js#146

willNavigate is a listner for "will-navigate" event see:
https://searchfox.org/mozilla-central/rev/358f816f63da072145c593e9e2ac36b7250ecd25/devtools/client/netmonitor/src/connector/firefox-connector.js#74

You can also note the comment:
// If the log is persistent, just clear all accumulated timing markers.

2. So, if persist-log is true we want to clearTimingMarkers and also reset the new firstStartedMillisInTheLastReload, so it's set again when the first request is intercepted.

So, when looking at this I think that clearTimingMarkers could do all that: clear timing markers and also reset the time of the first request

if (this.actions) {
if (!Services.prefs.getBoolPref("devtools.netmonitor.persistlog")) {
this.actions.batchReset();
this.actions.clearRequests();
} else {
// If the log is persistent, just clear all accumulated timing markers.
this.actions.clearTimingMarkers();
}
}

3. The new firstStartedMillisInTheLastReload can actually part of the TimingMarkers reducer (since it's the reducers responsible for the timing markers)
   https://searchfox.org/mozilla-central/rev/358f816f63da072145c593e9e2ac36b7250ecd25/devtools/client/netmonitor/src/reducers/timing-markers.js#13

function TimingMarkers() {
return {
firstDocumentDOMContentLoadedTimestamp: -1,
firstDocumentLoadTimestamp: -1,
firstDocumentRequestStart: +Infinity,
};
}

Note, that I used a better name now!

4. The TimingMarkers needs to handle also ADD_REQUEST action and maintain that new field. In the same way as the Requests reducers does

Something like:

// Update the started/ended timestamps.
const { startedMillis } = action.data;
if (startedMillis < state.firstDocumentRequestStart) {
nextState.firstDocumentRequestStart = startedMillis;
}

5. The selector getDisplayedTimingMarker will use the field from TimingMarkers not from Requests reducer, which actually feels even better!

Would that work?

Honza

Comment 9

[Hemakshi Sachdev [:hemakshis]]

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #8)

(In reply to Hemakshi Sachdev [:hemakshis] she/her from comment #7)

function TimingMarkers() {
return {
firstDocumentDOMContentLoadedTimestamp: -1,
firstDocumentLoadTimestamp: -1,
firstDocumentRequestStart: +Infinity,
};
}

Note, that I used a better name now!

4. The TimingMarkers needs to handle also ADD_REQUEST action and maintain that new field. In the same way as the Requests reducers does

Something like:

// Update the started/ended timestamps.
const { startedMillis } = action.data;
if (startedMillis < state.firstDocumentRequestStart) {
nextState.firstDocumentRequestStart = startedMillis;
}

I really didn't knew that we can have multiple reducer calls for the same action. Learnt something new :)

5. The selector getDisplayedTimingMarker will use the field from TimingMarkers not from Requests reducer, which actually feels even better!

Would that work?

Yes, in fact, your solution is way more elegant! Now I am feeling really stupid for giving such bad a solution :(

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c48b22d152f2
Reset DOMContentLoaded and load metrics on Reload while Persist Logs is enabled. r=Honza

Comment 11

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/c48b22d152f2

Comment 12

[gj]

(In reply to Hemakshi Sachdev [:hemakshis] from comment #9)

Yes, in fact, your solution is way more elegant! Now I am feeling really stupid for giving such bad a solution :(

You shouldn't feel stupid at all — your contributions are valuable, and I, for one, am grateful to anyone who tries to make Firefox a better browser. Thank you!