1111412 - Slow script timer relies on Ion to trigger on time

Status: RESOLVED FIXED

(Core :: XPConnect, defect)

Description

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

I was looking at the slow script code today and I found something strange. Let's assume the slow script timeout is set to 10 seconds. The watchdog code triggers the JS interrupt callback when we've been in a request for 10 seconds or more. However, that's not enough to get a slow script dialog. Instead, we need to wait for another timer, mSlowScriptCheckpoint, to exceed 10 seconds. In the worst case, we can wait 20 seconds to get the dialog.

Typically, the worst case doesn't happen for an odd reason. Most "slow" scripts will enter Ion pretty quickly. And whenever an off-thread Ion compilation completes, we trigger the interrupt callback. We rely on that first interrupt callback, near when the script starts, to set mSlowScriptCheckpoint to the current time. Then, once the watchdog timer fires, mSlowScriptCheckpoint will already have been about 10 seconds ago.

However, it's possible that the slow script won't cause Ion compilation, in which case we'll have to wait 20 seconds to see the dialog: first we wait 10 seconds to trigger the watchdog timer and set mSlowScriptCheckpoint to the current time, and then another 10 seconds until the current time is > mSlowScriptCheckpoint+(10 seconds).

Anyway, this sucks and we should fix it. It's pretty easy to reproduce this by disabling Ion (or just off-thread compilation) and running a JS loop that waits 15 seconds. You won't see the dialog.

Comment 1

[Boris Zbarsky [:bzbarsky]]

OK.  So this wasn't much of an issue back when we set up the watchdog for 1s because we'd worst case put up the dialog after 11s instead of 10s.  But once we started setting the watchdog for the time we actually want to get the interrupt at we can end up with an actual run time anywhere from "about the pref time" to "twice the pref time"...

I agree this is not great.  Could we somehow set mSlowScriptCheckpoint from something other than an interrupt (e.g. from an AutoEntryScript)?

Comment 2

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

What about setting it in nsXPConnect::OnProcessNextEvent? That has a nice symmetry with clearing it in AfterProcessNextEvent.

Comment 3

[Luke Wagner [:luke]]

I can confirm what you're seeing but, until recently, if I put a printf in JS_RequestInterruptCallback, it would fire every second, starting after 1 the first second spent in JS call.  I guess this changed recently?

Comment 4

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

(In reply to Luke Wagner [:luke] from comment #3)
> I can confirm what you're seeing but, until recently, if I put a printf in
> JS_RequestInterruptCallback, it would fire every second, starting after 1
> the first second spent in JS call.  I guess this changed recently?

I haven't looked at the patches, but it sounds like something happened in bug 870043 that affected this.

Comment 5

[Brian Hackett [Laid off!]]

(In reply to Luke Wagner [:luke] from comment #3)
> I can confirm what you're seeing but, until recently, if I put a printf in
> JS_RequestInterruptCallback, it would fire every second, starting after 1
> the first second spent in JS call.  I guess this changed recently?

This changed recently in bug 1091459.  Triggering the interrupt every second was causing regular expression execution to bail out before it was necessary (we can't handle interrupts with regexp jitcode on the stack).  I guess bug 1091459 should have done something with mSlowScriptCheckpoint but this problem didn't show up in testing and I don't see any real comments on what mSlowScriptCheckpoint is supposed to mean and how it is set.  It seems like there is a lot of overlap between mSlowScriptCheckpoint and TimestampRuntimeStateChange, except when the user hits 'continue' on the slow script dialog?

Comment 6

[Bobby Holley (:bholley)]

(In reply to Bill McCloskey (:billm) from comment #2)
> What about setting it in nsXPConnect::OnProcessNextEvent? That has a nice
> symmetry with clearing it in AfterProcessNextEvent.

I think it should live in AutoEntryScript/~AutoEntryScript, since that's a tighter bound on where we enter/exit script.

Comment 7

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

Don't we want the loosest possible bound? If we reset the timer too often, we won't get the slow script dialog. For example, if we use ~AutoEntryScript, we would have to keep track of the nesting depth. We should only reset the timer if the depth is zero.

Comment 8

[Bobby Holley (:bholley)]

(In reply to Bill McCloskey (:billm) from comment #7)
> Don't we want the loosest possible bound? If we reset the timer too often,
> we won't get the slow script dialog.

Hm, I guess that's true in the case of a page having a zillion event listeners for an event, each of which takes 5 seconds.

> For example, if we use
> ~AutoEntryScript, we would have to keep track of the nesting depth. We
> should only reset the timer if the depth is zero.

It depends on what you're trying to do. Both AutoEntryScript and event processing can be nested - it's just a question of where you're interested in resetting the timer. But yes, I agree that event processing is probably better here.

Comment 9

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

Attachment: fix-slow-script-timer

I considered doing the timer stuff only when mEventDepth==0. However, I'm concerned that we might get spurious slow script warnings when we're showing a modal dialog or something.

Comment 10

[Bobby Holley (:bholley)]

Comment on attachment 8537975 [details] [diff] [review]
fix-slow-script-timer

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

r=me modulo that.

::: js/xpconnect/src/xpcprivate.h
@@ +633,1 @@
>      void OnAfterProcessNextEvent() { mSlowScriptCheckpoint = mozilla::TimeStamp(); }

Is there any reason for the asymmetry in Now vs NowLoRes? Seems like we should do one or the other.

Comment 11

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

Don't we use NowLowRes() everywhere in the slow script code?

Comment 12

[Bobby Holley (:bholley)]

(In reply to Bill McCloskey (:billm) from comment #11)
> Don't we use NowLowRes() everywhere in the slow script code?

Oh, I guess mozilla::TimeStamp() creates a sentinel timestamp rather than Now. Nevermind.

Comment 13

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/f49d4632197b

Comment 14

[Ryan VanderMeulen [:RyanVM]]

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

Comment 15

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

I'm going to back this out on 37 since I'm running into a little bit of trouble getting the patch in bug 1114345 to pass tests.

Comment 16

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

Attachment: backout

Do I need approval to back out a bug?

Approval Request Comment
[Feature/regressing bug #]: this one
[User impact if declined]: slow script dialog may appear supriously when laptop wakes up
[Describe test coverage new/current, TreeHerder]: none
[Risks and why]: very low; this just reverts some simple code to a previous state
[String/UUID change made/needed]: none

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/847465376f09