Open Bug 1276626 Opened 3 years ago Updated 10 months ago

Matching strings on regular expressions including ([\s\S]+?) is very slow

Categories

(Core :: JavaScript Engine, defect)

48 Branch
defect
Not set

Tracking

()

People

(Reporter: hsteen, Assigned: arai)

References

()

Details

Attachments

(2 files)

Attached file wc2600.htm test case
According to https://webcompat.com/issues/2600 , blog.chromium.org tends to throw up slow script warnings. I get them sometimes too, and the cause seems to be a regexp match() that takes many seconds to complete. Maybe there's room for a hack to optimize this case..? See attached test case.
Needinfo arai as they probably know most about our regexp machinery right now.

Safari is also very slow at this, whereas Chrome finishes the test case in ~6700ms on my machine. Since we share v8's regexp JIT, I'd assume they have some kind of optimization for this case.
Flags: needinfo?(arai.unmht)
The time taken by the test case differs by the value of dom.max_script_run_time pref.
  dom.max_script_run_time=0  : 6749ms
  dom.max_script_run_time=10 : 41903ms  (slow script dialog is shown 3 times)

Also, it takes 6593ms on shell.

So, looks like, slow script dialog, check code, interrupt or something around them make the RegExp matching slower.  (interrupt is suspicious...)
will look into it.
round up from IRC discussion.

This is caused by interrupt, that is invoked at half timing, so after running 5 seconds.
then RegExp execution fallbacks to interpreter, and interpreter execution takes more than 30 seconds.

So, there are 2 possible solutions:
  1. move the half timing check to watchdog, and interrupt only for full timeout (10 seconds)
  2. call interrupt callback inside RegExp JIT code, and don't fallback to interpreter on interrupt
Flags: needinfo?(arai.unmht)
See Also: → 1114345
Ideally, we'd do both: it seems like the half-time tracking[1] happening in the WatchDog would make more sense, and would probably be slightly more optimal for other code, too.

2) is more important, though: for cases where the slow-script warning is shown but the user chooses to continue running the script, it's rather unfortunate for it take take much longer. The current solution all but guarantees that at least two slow-script warnings will be shown: the original execution in the regexp JIT took at least 5s. After that, we fall back to the interpreter, spend another 5s, and then show the slow script dialog. Assuming the interpreter is 3x slower, it'll take at least 15s, so we'll show a second warning at the 20s mark.

[1] https://dxr.mozilla.org/mozilla-central/rev/4d63dde701b47b8661ab7990f197b6b60e543839/js/xpconnect/src/XPCJSRuntime.cpp#1305
BTW, I was playing around a bit trying to find a recommendation for the website - turns out removing the first question mark (str.match(/([\s\S]+)<div data-is-preview.+?>([\s\S]+?)<\/div>/m);) makes the performance problems even worse. Now we're suddenly talking more than a minute in Chrome and several hundred seconds in Firefox..
As a first step, moved `SlowScriptSecondHalf` check into watchdog.

Before this patch, interrupt callback is initially called at T/2 timing, and then called every second after T/2 if runtime is active.
I guess, it's called every second to minimize the interval between 2 slow script dialogs, but it's too high cost, as most of interrupt are just ignored in handler.

We should invoke interrupt handler only at T, 2*T, 3*T, ..., i*T timing.
(with this, we have to wait at most 2*T-1 seconds between 2 dialogs tho...)

So, added mSlowScriptSecondHalfCount member to Watchdog, that is incremented every T/2.
(to do that, compare "elapsed time since TimestampRuntimeStateChange" with |(mSlowScriptSecondHalfCount + 1) * T/2|, and if elapsed time is greater, increment mSlowScriptSecondHalfCount)

then, if the value of mSlowScriptSecondHalfCount after increment is even, interrupt callback is called.

The other `SlowScriptSecondHalf` related code in XPCJSRuntime::InterruptCallback and other methods are just backed out, as everything is now handled in watchdog.
Assignee: nobody → arai.unmht
Attachment #8758146 - Flags: review?(till)
Comment on attachment 8758146 [details] [diff] [review]
Part 1: Invoke interrupt handler only after MinScriptRunTimeSeconds elapsed.

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

Looks good to me. I'm not an xpconnect peer however, so just f+ and r?mrbkap.

::: js/xpconnect/src/XPCJSRuntime.cpp
@@ +1338,5 @@
> +        //   + <-- mSlowScriptSecondHalfCount = 3
> +        //   |
> +        //   | T/2
> +        //   |
> +        //   + <-- mSlowScriptSecondHalfCount = 4

Do we need the count? The alternative would be do what the old implementation did and just have a bool saying "we're in the second half of the timeout period", and reset that together with the timestamp. Not important, as this should work just fine.
Attachment #8758146 - Flags: review?(till)
Attachment #8758146 - Flags: review?(mrbkap)
Attachment #8758146 - Flags: feedback+
(In reply to Till Schneidereit [:till] from comment #7)
> Comment on attachment 8758146 [details] [diff] [review]
> Part 1: Invoke interrupt handler only after MinScriptRunTimeSeconds elapsed.
> 
> Review of attachment 8758146 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good to me. I'm not an xpconnect peer however, so just f+ and r?mrbkap.
> 
> ::: js/xpconnect/src/XPCJSRuntime.cpp
> @@ +1338,5 @@
> > +        //   + <-- mSlowScriptSecondHalfCount = 3
> > +        //   |
> > +        //   | T/2
> > +        //   |
> > +        //   + <-- mSlowScriptSecondHalfCount = 4
> 
> Do we need the count? The alternative would be do what the old
> implementation did and just have a bool saying "we're in the second half of
> the timeout period", and reset that together with the timestamp. Not
> important, as this should work just fine.

TimestampRuntimeStateChange is exposed to script etc via Components.utils.getWatchdogTimestamp:
https://dxr.mozilla.org/mozilla-central/rev/4d63dde701b47b8661ab7990f197b6b60e543839/js/xpconnect/idl/xpccomponents.idl#620

So I want to keep the value same as before.
(In reply to Tooru Fujisawa [:arai] from comment #8)
> TimestampRuntimeStateChange is exposed to script etc via
> Components.utils.getWatchdogTimestamp:
> https://dxr.mozilla.org/mozilla-central/rev/
> 4d63dde701b47b8661ab7990f197b6b60e543839/js/xpconnect/idl/xpccomponents.
> idl#620
> 
> So I want to keep the value same as before.

Ah, ok. Then that's required, yes.
Attachment #8758146 - Flags: review?(mrbkap) → review+
Thank you :)

will land Part 1 first.
Keywords: leave-open
Pushed by arai_a@mac.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8272530c90ef
Part 1: Invoke interrupt handler only after MinScriptRunTimeSeconds elapsed. r=mrbkap
See Also: → 1286946
See Also: 1286946
Duplicate of this bug: 1286946
Depends on: 1284511
Backout by kwierso@gmail.com:
https://hg.mozilla.org/mozilla-central/rev/176aff980979
Backed out changeset 8272530c90ef for bug 1284511 r=blassey a=merge
[NI overholt -- want to chat about this one re FF 50+]
Flags: needinfo?(overholt)
If we try landing this again do we have a plan for the more frequent slow script dialogs (bug 1284511)?
Flags: needinfo?(overholt) → needinfo?(arai.unmht)
I need to figure out why the patch doesn't work even after the fix in bug 1284511 (not backout).
I'm still failing to reproduce the slow script dialog after sleep, so it's hard to investigate...
Flags: needinfo?(arai.unmht)
See Also: → 1308555
The leave-open keyword is there and there is no activity for 6 months.
:arai, maybe it's time to close this bug?
Flags: needinfo?(arai.unmht)
afaik, This bug itself is still valid.

(just that I have no reproducible env and no idea why it fails, maybe I can retry given I have different set of machines now)

anyway, removing leave-open.
Flags: needinfo?(arai.unmht)
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.