1225097 - [e10s] HTTP_* probes that regress under e10s

Status: RESOLVED DUPLICATE of bug 1253379

(Firefox :: General, defect, P1)

Description

[Roberto Agostino Vitillo (:rvitillo)]

The histogram regressed in e10s. See provided URL and grep for the metric's name.

Comment 1

[Roberto Agostino Vitillo (:rvitillo)]

See also:
HTTP_PAGE_COMPLETE_LOAD_CACHED_V2
HTTP_PAGE_COMPLETE_LOAD

Comment 2

[Jim Mathies [:jimm]]

Hey Roberto, can we get a refresh of this now that bug 1217571 is fixed on aurora?

Comment 5

[Roberto Agostino Vitillo (:rvitillo)]

Jim, you can monitor the progress of this probe from the Telemetry dashboard:

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0

Comment 6

[Jim Mathies [:jimm]]

Hey Honza, I'm trying to figure out if this is a regression we should be concerned about. The

Comment 7

[Jim Mathies [:jimm]]

(In reply to Jim Mathies [:jimm] from comment #6)
> Hey Honza, I'm trying to figure out if this is a regression we should be
> concerned about. The

ignore this, he wasn't accepting needinfos. I need to find someone else.

Comment 8

[Jim Mathies [:jimm]]

*no* regressions:

HTTP_PAGE_COMPLETE_LOAD_CACHED_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0

regressions:

HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- lower bucket regression

Comment 9

[Jim Mathies [:jimm]]

jld, any chance you might be able to shed some light on these probes? We're curious if we need to dig into the missing data in the lower buckets.

Comment 10

[Jed Davis [:jld] ⟨⏰|UTC-7⟩ ⟦he/him⟧]

Sorry; I don't think I know anything useful about this part of Necko.  Handing off the needinfo to jduell, who might have a better idea of what's going on, and/or who else in networking to ask.

Comment 11

[Jim Mathies [:jimm]]

latest set:

no regression:
HTTP_SUB_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-19&table=0&trim=1&use_submission_date=0
HTTP_SUB_COMPLETE_LOAD_CACHED_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-19&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD_CACHED_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0

regressions:
HTTP_SUB_REVALIDATION
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_REVALIDATION&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-19&table=0&trim=1&use_submission_date=0
- right shift of data
HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-11-16&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-10&table=0&trim=1&use_submission_date=0
- lower bucket regression

Comment 12

[Jim Mathies [:jimm]]

Updated dates:

no regression:
HTTP_SUB_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
HTTP_SUB_COMPLETE_LOAD_CACHED_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD_CACHED_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0

regressions:
HTTP_SUB_REVALIDATION
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_REVALIDATION&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
- right shift of data
HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
- no hits in the 0 bucket.
HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&start_date=2015-11-19&end_date=2015-11-23&keys=__none__!__none__!__none__&max_channel_version=aurora%252F44&measure=HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&table=0&trim=1&use_submission_date=0
- lower bucket regression

Comment 13

[Jason Duell]

Honza/Michal, can you look at these and see if we've got any idea why they've slower on e10s?

It's odd--I was seeing improved network channel load times when I did an experiment a while ago with e10s: see bug 1062713 comment 10.  Of course, there's a lot more moving parts involved in the overall page load time.

Comment 14

[Jim Mathies [:jimm]]

Here are updated graphs from the beta experiment - 

Generally, e10s does better in general with a few of these probes experiencing fewer lower bucket hits. The general gains I'm seeing here indicate e10s is performing better.

HTTP_SUB_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD_CACHED_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_PAGE_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_PAGE_COMPLETE_LOAD
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_PAGE_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUBITEM_FIRST_BYTE_LATENCY_TIME&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_FIRST_SENT_TO_LAST_RECEIVED&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_SUB_REVALIDATION
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_REVALIDATION&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2:
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0
HTTP_SUB_COMPLETE_LOAD_CACHED_V2
https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0

Comment 15

[Jim Mathies [:jimm]]

current regressions:

HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2:

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0

2% vs. 9% lowest bucket hits. the worst regression of the set.

HTTP_SUB_COMPLETE_LOAD,
HTTP_SUB_COMPLETE_LOAD_CACHED_V2

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_COMPLETE_LOAD&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_COMPLETE_LOAD_CACHED_V2&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0

.15% vs. 1.89% lowest bucket hits. small, possibly insignificant regression.

HTTP_SUB_REVALIDATION

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2015-12-08&keys=__none__!__none__!__none__&max_channel_version=beta%252F43&measure=HTTP_SUB_REVALIDATION&min_channel_version=null&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2015-11-26&table=0&trim=1&use_submission_date=0

.02% vs. 1.56% lowest bucket hits. small, possibly insignificant regression.

Comment 16

[Jim Mathies [:jimm]]

For the HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2 regression, it seems reasonable to me this would happen since the cache is in the parent and the request is made in the child. A slight 0 ms regression in a probe that measures 'HTTP page: Open -> cache read start (ms)' seems reasonable. The difference is accounted for in the higher 1-2ms, 2-3ms, and 3-4ms values that follow.

For HTTP_SUB_COMPLETE_LOAD, which measures 'HTTP subitem: Overall load time - all (ms)' we see an large improvement under e10s for values > 3ms, with a small regression in numbers at 0ms. I'm going to posit that this is caused by latency in the network request made between processes. Overall we see good improvement here.

The same pattern can be seen in HTTP_SUB_COMPLETE_LOAD_CACHED_V2 which measures 'HTTP subitem: Overall load time - cache hits (ms) [cache2]'.

Lastly we have HTTP_SUB_REVALIDATION, which measures 'HTTP subitem: Positive cache validation time (ms)'. According to the code this measures the difference between a request start and a response end. Again we have a regression between 0->7ms, with substantial improvements beyond that range under e10s. I think we can mark this up similarly as being added latency on the low end due to cross process request times.

I'm going to close this out because I don't feel we need to block on it. If anyone cc'd in or ni'd here disagrees please reopen and explain why.

Comment 17

[Jim Mathies [:jimm]]

From the beta no addons experiment report we have new regressions here that are more explicit compared to the old aurora data.

https://github.com/vitillo/e10s_analyses/blob/master/beta45-withoutaddons/e10s_experiment.ipynb

search for:

HTTP_PAGE_OPEN_TO_FIRST_FROM_CACHE_V2
HTTP_PAGE_COMPLETE_LOAD_CACHED_V2
HTTP_PAGE_COMPLETE_LOAD
HTTP_SUB_COMPLETE_LOAD_CACHED_V2
HTTP_SUB_COMPLETE_LOAD"
HTTP_SUB_REVALIDATION
HTTP_SUB_OPEN_TO_FIRST_FROM_CACHE_V2

Comment 19

[Honza Bambas (:mayhemer)]

I'd more say bug 1253379.