Closed Bug 1064706 Opened 10 years ago Closed 10 years ago

[e10s] Report resource-timing in the content process

Categories

(Core :: Networking, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla36
Tracking Status
e10s + ---
firefox35 --- fixed
firefox36 --- fixed

People

(Reporter: valentin, Assigned: valentin)

References

Details

Attachments

(5 files, 6 obsolete files)

7.04 KB, patch
mayhemer
: review+
Details | Diff | Splinter Review
12.80 KB, patch
valentin
: review+
Details | Diff | Splinter Review
5.03 KB, patch
valentin
: review+
Details | Diff | Splinter Review
14.52 KB, patch
Details | Diff | Splinter Review
12.78 KB, patch
Details | Diff | Splinter Review
window.performance.getEntries() returns [] in e10s, as the HttpChannelChild does not record any timing info, and the info from the parent is not passed down to the child.

The simplest approach would be to add an IPDL call, which would get called in OnStopRequest.
The timing info seems to be already there, but we need to add the entries to the Performance instance in the content process.
Summary: [e10s] send resource timing data to the content process → [e10s] Report resource-timing in the content process
Assignee: nobody → valentin.gosu
Status: NEW → ASSIGNED
Comment on attachment 8496297 [details] [diff] [review]
Send timing info to content process

Review of attachment 8496297 [details] [diff] [review]:
-----------------------------------------------------------------

I would suggest that instead of sending a separate Timing IPDL message you

1) define a struct in netwerk/ipc/NeckoChannelParams.ipdlh that has all the various timings in it and 

2) send one of those in the OnStopRequest message

In general the fewer IPDL messages the better (even if it mean we send one big one) since each IPDL message may involve a lot of overhead (context switches, etc)
Attachment #8495532 - Attachment is obsolete: true
Attachment #8496297 - Attachment is obsolete: true
Attachment #8497181 - Flags: review?(honzab.moz)
Comment on attachment 8497182 [details] [diff] [review]
Send timing info to content process

This patch works in sending the timing data to the content process, however there is a small issue:
One of the w3c tests fails because the startTime is about 30-40 ms off from the expected value, while the allowed delta is up to 20 ms.

The problem is that the timing info is relative to nsDOMNavigationTiming::mNavigationStartTimeStamp, and the parent/content process have slightly different values for this, as they're created/initialized at different times.

I'm thinking of passing the value from the parent to the child, in an IPDL call. Does that sound fair? My guess is that it would go somewhere in TabParent, but not sure where.
Attachment #8497182 - Flags: review?(honzab.moz)
Comment on attachment 8497182 [details] [diff] [review]
Send timing info to content process

Review of attachment 8497182 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/protocol/http/HttpChannelChild.cpp
@@ +559,5 @@
> +  mTransactionTimings.responseStart = timing.responseStart;
> +  mTransactionTimings.responseEnd = timing.responseEnd;
> +  mAsyncOpenTime = timing.fetchStart;
> +  mRedirectStartTimeStamp = timing.redirectStart;
> +  mRedirectStartTimeStamp = timing.redirectEnd;

s/mRedirectStartTimeStamp/mRedirectEndTimeStamp/

::: netwerk/protocol/http/HttpChannelParent.cpp
@@ +228,5 @@
>    if (NS_FAILED(rv))
>      return SendFailedAsyncOpen(rv);
>  
>    mChannel = static_cast<nsHttpChannel *>(channel.get());
> +  mChannel->SetTimingEnabled(true);

shouldn't the setting be carried from the child?  (not sure now)
Attachment #8497182 - Flags: review?(honzab.moz) → review+
(In reply to Valentin Gosu [:valentin] from comment #8)
> Comment on attachment 8497182 [details] [diff] [review]
> Send timing info to content process
> 
> This patch works in sending the timing data to the content process, however
> there is a small issue:
> One of the w3c tests fails because the startTime is about 30-40 ms off from
> the expected value, while the allowed delta is up to 20 ms.
> 
> The problem is that the timing info is relative to
> nsDOMNavigationTiming::mNavigationStartTimeStamp, and the parent/content
> process have slightly different values for this, as they're
> created/initialized at different times.
> 
> I'm thinking of passing the value from the parent to the child, in an IPDL
> call. Does that sound fair? My guess is that it would go somewhere in
> TabParent, but not sure where.

I may not fully understand (or just forgot how all this works).  AFAIK there is NO value for mNavigationStartTimeStamp in the parent, right?  So, it seems like when you subtract TimeStamp values captured on the parent from something captured on the child you can never get a precise time anyway.  Maybe you should somehow adjust the values on the child?
Attachment #8497181 - Flags: review?(honzab.moz) → review+
(In reply to Honza Bambas (:mayhemer) from comment #9)
> > +  mRedirectStartTimeStamp = timing.redirectEnd;
> 
> s/mRedirectStartTimeStamp/mRedirectEndTimeStamp/

Oops. Nice catch. Thanks!

> 
> ::: netwerk/protocol/http/HttpChannelParent.cpp
> @@ +228,5 @@
> >    if (NS_FAILED(rv))
> >      return SendFailedAsyncOpen(rv);
> >  
> >    mChannel = static_cast<nsHttpChannel *>(channel.get());
> > +  mChannel->SetTimingEnabled(true);
> 
> shouldn't the setting be carried from the child?  (not sure now)

Probably should, however, it seems that we SetTimingEnabled(true) for any channel that implements nsITimedChannel. So we should probably do the same here, in order to gather timing info on the parent.
Comment on attachment 8497193 [details] [diff] [review]
Enable dom/testing/mochitest/general/ tests under e10s

Boris, do you think this is ok?
I did a try push and kept the ones that failed disabled.

With these patches applied, there are no obvious failures here. I'll do another one just in case.
https://tbpl.mozilla.org/?tree=Try&rev=444a22ef601a
Attachment #8497193 - Flags: review?(bzbarsky)
Comment on attachment 8497193 [details] [diff] [review]
Enable dom/testing/mochitest/general/ tests under e10s

>+  SpecialPowers.pushPrefEnv({"clear":[["dom.enable_resource_timing"]]}, SimpleTest.finish);

No need.  pushPrefEnv records the changes made and reverts them after the test is done.

r=me modulo that.
Attachment #8497193 - Flags: review?(bzbarsky) → review+
Attachment #8497182 - Attachment is obsolete: true
Attachment #8500326 - Flags: review+
Attachment #8497193 - Attachment is obsolete: true
Attachment #8500327 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/19cc89734f2d
https://hg.mozilla.org/mozilla-central/rev/afecbcdbe6d5
https://hg.mozilla.org/mozilla-central/rev/30e935a33442
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla35
Depends on: 1080301
I backed out part 2 and 3 because part 2 was causing severe leaks on E10s, which makes using Nightly with e10s quite unpleasant.

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/0edf78ed6139
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/6a26e53f9b72
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla35 → ---
Comment on attachment 8507578 [details] [diff] [review]
Save timing info in nsPerformanceTiming to avoid keeping a ref to the channel

It seems that the e10s leaks were due to us holding a ref to the channel in nsPerformanceTiming. Keeping the timestamps in nsPerformanceTiming does make the object a bit larger, but it also means we don't need to keep the sub-resource channels alive for longer than needed.
Attachment #8507578 - Flags: review?(bzbarsky)
Changed the patch because of failures in https://treeherder.mozilla.org/ui/logviewer.html#?job_id=2537647&repo=try
We can keep a ref to the channel in nsPerformance, but not nsPerformanceTiming (which causes the leaks).
New try run looks good: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=8523cf2fabb0
Attachment #8507857 - Flags: review?(bzbarsky)
Attachment #8507578 - Attachment is obsolete: true
Attachment #8507578 - Flags: review?(bzbarsky)
Comment on attachment 8507857 [details] [diff] [review]
Save timing info in nsPerformanceTiming to avoid keeping a ref to the channel

> It seems that the e10s leaks were due to us holding a ref to the channel

Hmm.  Why?  Channels aren't supposed to hold backrefs after OnStopRequest.

This looks fine if you initialize the new bool/uint16_t members in the ctor, but I'd like to understand why it's needed at all....
Attachment #8507857 - Flags: review?(bzbarsky) → review+
(In reply to Boris Zbarsky [:bz] from comment #23)
> Comment on attachment 8507857 [details] [diff] [review]
> Save timing info in nsPerformanceTiming to avoid keeping a ref to the channel
> 
> > It seems that the e10s leaks were due to us holding a ref to the channel
> 
> Hmm.  Why?  Channels aren't supposed to hold backrefs after OnStopRequest.

From what I can recall :jduell told me that we do keep HttpChannelChild alive after OnStopRequest for some IPDL reasons.

> 
> This looks fine if you initialize the new bool/uint16_t members in the ctor,
> but I'd like to understand why it's needed at all....

Should I move the initializations from InitializeTimingInfo to the constructor?
> Should I move the initializations from InitializeTimingInfo to the constructor?

Just init them to something in the ctor so they don't have garbage values when we have no timed channel.  0/false/whatever are good values.
Attachment #8507857 - Attachment is obsolete: true
https://hg.mozilla.org/mozilla-central/rev/7b6c3c0e7ea6
https://hg.mozilla.org/mozilla-central/rev/56e812ffe573
https://hg.mozilla.org/mozilla-central/rev/949644ee3fdd
Status: REOPENED → RESOLVED
Closed: 10 years ago10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
Please land at least the last part on Aurora to fix the memory regression in bug 1079705.
Flags: needinfo?(valentin.gosu)
Comment on attachment 8500326 [details] [diff] [review]
Send timing info to content process

Approval Request Comment
[Feature/regressing bug #]:
Bug 1002855 caused a ~10Mb memory regression, by keeping subresource channels alive for longer than needed. This is fixed by attachment 8508326 [details] [diff] [review], posted in this bug.
[User impact if declined]:
Memory regression. Running firefox in e10s mode will return an empty array of resourceTiming objects.
[Describe test coverage new/current, TBPL]:
We have two mochitests and a web-performance test. This fix has been on m-c for a few days.
[Risks and why]: 
Low risks.
[String/UUID change made/needed]:
None.

This patch sends the timing info over IPDL to the content process.
Flags: needinfo?(valentin.gosu)
Attachment #8500326 - Flags: approval-mozilla-aurora?
Comment on attachment 8500327 [details] [diff] [review]
Enable dom/testing/mochitest/general/ tests under e10s

Approval Request Comment (see comment 30)

This patch enables tests under e10s.
Attachment #8500327 - Flags: approval-mozilla-aurora?
Comment on attachment 8508326 [details] [diff] [review]
Save timing info in nsPerformanceTiming to avoid keeping a ref to the channel

Approval Request Comment (see comment 30)

This patch is the one that fixes the AWSY regression. Instead of keeping a ref to the httpChannel(Child) it copies the timestamps to nsPerformanceTiming.
Attachment #8508326 - Flags: approval-mozilla-aurora?
Attachment #8500326 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8500327 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8508326 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Needs rebasing for Aurora uplift.
Flags: needinfo?(valentin.gosu)
- rebased for aurora
From what I could tell, this was the only patch needing to be rebased.
Let me know if I can help in any other way. Thanks, Ryan!
Flags: needinfo?(valentin.gosu)
Depends on: 1139831
Depends on: 1253379
You need to log in before you can comment on or make changes to this bug.