1271978 - Record js slow script dialog delay in telemetry

Status: RESOLVED FIXED

(Core :: XPConnect, defect)

Description

[Jim Mathies [:jimm]]

Testing in bug 1260769 found that the slow script notification may be more responsive under e10s. Add a probe that measures the difference between slow script timeout prefs and the actual time it takes to trigger the notification. compare these values under e01s and non-e10s.

prefs:
dom.max_script_run_time
dom.max_chrome_script_run_time

Comment 1

[Jim Mathies [:jimm]]

Attachment: patch

Adds a telemetry probe for content timeouts.

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Comment on attachment 8751451 [details] [diff] [review]
patch

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

::: js/xpconnect/src/XPCJSRuntime.cpp
@@ +1364,5 @@
>      // care of that case.
>      if (self->mSlowScriptCheckpoint.IsNull()) {
>          self->mSlowScriptCheckpoint = TimeStamp::NowLoRes();
>          self->mSlowScriptSecondHalf = false;
> +        self->mSlowScriptActualWait = 0;

This would be cleaner as |mSlowScriptActualWait = mozilla::TimeDuration()|.

@@ +1436,5 @@
>      }
>  
> +    // Accumulate slow script invokation delay.
> +    if (!chrome && !self->mTimeoutAccumulated) {
> +      uint32_t delay = uint32_t(floor(self->mSlowScriptActualWait.ToMilliseconds() - (limit * 1000.0)));

I don't think you need floor here.

@@ +3712,5 @@
>  
>      // Start the slow script timer.
>      mSlowScriptCheckpoint = mozilla::TimeStamp::NowLoRes();
>      mSlowScriptSecondHalf = false;
> +    mSlowScriptActualWait = 0;

Same as above.

Comment 3

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1a022b6b949c

Comment 4

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1a022b6b949c

Comment 5

[Jim Mathies [:jimm]]

Comment on attachment 8751451 [details] [diff] [review]
patch

Approval Request Comment
[Feature/regressing bug #]:
no  bug, e10s related diagnostic telemetry probe
[User impact if declined]:
none
[Describe test coverage new/current, TreeHerder]:
on mc for a day or so
[Risks and why]: 
low, well understood code changes
[String/UUID change made/needed]:
none

Comment 6

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8751451 [details] [diff] [review]
patch

Telemetry data on slow script dialog delay, Aurora48+, Beta47+

Comment 7

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Hi Jim, for new telemetry probes that need uplift to Aurora/Beta, it would be nice if we can verify the expected data is coming on Nightly before uplifting to Aurora/Beta. This is to avoid unnecessary churn. Thanks!

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b27e0175db55

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/a9e1d0bc8a8c

Comment 10

[Jim Mathies [:jimm]]

(In reply to Ritu Kothari (:ritu) from comment #7)
> Hi Jim, for new telemetry probes that need uplift to Aurora/Beta, it would
> be nice if we can verify the expected data is coming on Nightly before
> uplifting to Aurora/Beta. This is to avoid unnecessary churn. Thanks!

Data is starting to trickle in from nightly - 

https://telemetry.mozilla.org/new-pipeline/dist.html#!compare=e10sEnabled&cumulative=0&end_date=2016-05-13&keys=__none__!__none__!__none__&max_channel_version=nightly%252F49&measure=SLOW_SCRIPT_NOTIFY_DELAY&min_channel_version=null&product=Firefox&sanitize=0&sort_keys=submissions&start_date=2016-05-13&table=0&trim=0&use_submission_date=0

Comment 11

[Jim Mathies [:jimm]]

Attachment: SLOW_SCRIPT_NOTIFY_DELAY pings.png

The distribution is interesting as well as the raw number of pings we receive back from the browser. Currently under e10s we are receiving 7x more telemetry pings containing this probe.

Comment 12

[Jim Mathies [:jimm]]

(In reply to Jim Mathies [:jimm] from comment #11)
> Created attachment 8752780 [details]
> SLOW_SCRIPT_NOTIFY_DELAY pings.png
> 
> The distribution is interesting as well as the raw number of pings we
> receive back from the browser. Currently under e10s we are receiving 7x more
> telemetry pings containing this probe.

In thinking about this, the 7x number probably has to do with very few users running non-e10s on night/aurora. So this may not be significant.

Comment 13

[Jim Mathies [:jimm]]

(In reply to Wes Kocher (:KWierso) from comment #9)
> https://hg.mozilla.org/releases/mozilla-beta/rev/a9e1d0bc8a8c

Hey Ritu, do you know what beta build this will land in?

Comment 14

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

(In reply to Jim Mathies [:jimm] from comment #13)
> (In reply to Wes Kocher (:KWierso) from comment #9)
> > https://hg.mozilla.org/releases/mozilla-beta/rev/a9e1d0bc8a8c
> 
> Hey Ritu, do you know what beta build this will land in?

Hi Jim, it should be in 47.0b6 (which we gtb today noon PST).