Regexp performance issue

RESOLVED FIXED in Firefox 34, Firefox OS v2.1

Status

()

Core
JavaScript Engine
RESOLVED FIXED
4 years ago
3 years ago

People

(Reporter: Pierre Réveillon, Assigned: bhackett)

Tracking

({regression})

33 Branch
mozilla36
regression
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox33 wontfix, firefox34+ fixed, firefox35+ fixed, firefox36+ fixed, firefox-esr31 unaffected, b2g-v1.4 unaffected, b2g-v2.0 affected, b2g-v2.0M affected, b2g-v2.1 fixed, b2g-v2.2 fixed)

Details

Attachments

(2 attachments)

(Reporter)

Description

4 years ago
Created attachment 8514100 [details]
Test case

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:32.0) Gecko/20100101 Firefox/32.0
Build ID: 20140924083558

Steps to reproduce:

Applying this Regexp on a very big string:
String.match(/([^\xA9]{400}|^[^\xA9]{0,400})(?:Copyright|\xA9|\(c\))[^\xA9]{0,400}/gi)



Actual results:

Takes more than 10 seconds.


Expected results:

The same test case was executed in less than a second on Firefox 31.
It takes ~2 seconds on the latest Google Chrome.
(Reporter)

Updated

4 years ago
Depends on: 1084280
OS: Linux → All
Hardware: x86_64 → All
(Reporter)

Comment 1

4 years ago
This bug is following the discussion on bug 1084280, that fixed the freeze and crash problems, but not the performance drop.

I just tested on Firefox 31.2.0 ESR, the test case takes ~200ms.
Confirmed.  In a nightly, I see the regexp complete in 9700ms on my hardware; in Chrome it takes about 1600ms.

[Tracking Requested - why for this release]: Performance regression
Status: UNCONFIRMED → NEW
tracking-firefox34: --- → ?
tracking-firefox35: --- → ?
tracking-firefox36: --- → ?
Ever confirmed: true
Keywords: regression

Comment 3

4 years ago
Benchmark on Mac OSX Maverick (10.9.5)
Firefox versions 31.2.0 and before: results in 220 to 260ms
Firefox versions from 32.0 to Aurora 35.0a2: no results. unresponsive script dialog
Nightly 36.0a1: results in 11200 to 11400ms
(Assignee)

Comment 4

4 years ago
Created attachment 8514481 [details] [diff] [review]
patch

OK, the issue here seems to be that for long running scripts the watchdog starts requesting interrupt callbacks after the script has been running for more than a second, regardless of what the pref value for showing the slow script dialog is.  This behavior goes back to bug 871079, with the issue being that the watchdog doesn't have a way to directly see what the preference's value is (since it isn't on the main thread, as required by Preferences::GetInt), so it fudges things and just requests an interrupt once a second.

So here we request the interrupt after a second, interrupt the regexp and restart it in the interpreter, and end up taking 10 seconds (or, before bug 1077514, never finish executing at all).  The attached patch adds some plumbing so that the watchdog has a local copy of the minimum script timeout value, which it uses to only trigger the interrupt callback when we might need to show the slow script dialog.  With this change the regexp finishes executing for me in 1800 ms or so.
Assignee: nobody → bhackett1024
Attachment #8514481 - Flags: review?(bobbyholley)
status-b2g-v1.4: --- → unaffected
status-b2g-v2.0: --- → affected
status-b2g-v2.0M: --- → affected
status-b2g-v2.1: --- → affected
status-b2g-v2.2: --- → affected
status-firefox33: --- → wontfix
status-firefox34: --- → affected
status-firefox35: --- → affected
status-firefox36: --- → affected
status-firefox-esr31: --- → unaffected
tracking-firefox34: ? → +
tracking-firefox35: ? → +
tracking-firefox36: ? → +
(Reporter)

Comment 5

4 years ago
It now takes ~2300ms with the patch, quite the same as in Chrome. Thanks Brian!
Comment on attachment 8514481 [details] [diff] [review]
patch

>+            mWatchdog->SetMinScriptRunTime(contentTime < chromeTime ? contentTime : chromeTime); // Where is Min()? :(

Looks like std::min is OK to use in our codebase at this point, yay.

Comment 7

4 years ago
I also thank you very much, Brian, for the patch! 
It solves many of our problems caused by this regression. I have to say, however, that there are still some nasty consequences of the performance drop (in my tests, approximately by a factor of 10 on some regexps: from 200ms to 2000ms in the above test case). I understand that irregexp caused this drop and that it will not be easy to fix but what I noticed is that when it leads to a non responsive script dialog, we never get the results, no matter how many times we click on continue. At this point I haven't been able to create a simple test case, outside of our context, with a single regular expression but I'll add it as soon as we manage to isolate one.

Comment 8

4 years ago
Added one non-irregexp-friendly pattern to bug 1084280 (crashes nightly). It is of these cases that do not yield results after multiple 'continue'.
Comment on attachment 8514481 [details] [diff] [review]
patch

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

r=bholley with those things addressed. Thanks for doing this!

::: js/xpconnect/src/XPCJSRuntime.cpp
@@ +1082,5 @@
>          mShuttingDown = false;
>          PR_NotifyCondVar(mWakeup);
>      }
>  
> +    int32_t MinScriptRunTime()

Call this MinScriptRunTimeSeconds (and do the same for the member and the setter) to make it clear that this isn't us.

@@ +1090,5 @@
> +
> +    void SetMinScriptRunTime(int32_t time)
> +    {
> +        MOZ_ASSERT(time > 0);
> +        mMinScriptRunTime = time;

Add a comment noting that this is atomic.

@@ +1110,5 @@
>  #include "ipc/Nuwa.h"
>  #endif
>  
> +#define PREF_MAX_SCRIPT_RUN_TIME_CONTENT "dom.max_script_run_time"
> +#define PREF_MAX_SCRIPT_RUN_TIME_CHROME "dom.max_chrome_script_run_time"

Please replace the other inline uses of these strings in this file.

@@ +1209,5 @@
> +    {
> +        // Convert infinitely long run time values so we can compute a minimum.
> +        int32_t pref = Preferences::GetInt(aPref, aDefault);
> +        if (pref <= 0 || pref > 60)
> +            return 60;

Not a fan of the random "60" here.

@@ +1226,5 @@
> +
> +        if (mWatchdog) {
> +            int32_t contentTime = GetScriptRunTimePreference(PREF_MAX_SCRIPT_RUN_TIME_CONTENT, 10);
> +            int32_t chromeTime = GetScriptRunTimePreference(PREF_MAX_SCRIPT_RUN_TIME_CHROME, 20);
> +            mWatchdog->SetMinScriptRunTime(contentTime < chromeTime ? contentTime : chromeTime); // Where is Min()? :(

We can use std::min now. So let's make this:

int32_t contentTime = Preferences::GetInt(PREF_MAX_SCRIPT_RUN_TIME_CONTENT, 10);
if (contentTime <= 0)
  contentTime = INT32_MAX;
int32_t chromeTime = Preferences::GetInt(PREF_MAX_SCRIPT_RUN_TIME_CHROME, 20);
if (chromeTime <= 0)
  chromeTime = INT32_MAX;
mWatchdog->SetMinScriptRunTime(std::min(contentTime, chromeTime));

And then kill GetScriptRunTimePreference.

@@ +1304,5 @@
>  
> +        // Don't request an interrupt callback unless the current script has
> +        // been running long enough that we might show the slow script dialog.
> +        // Triggering the callback from off the main thread can be expensive.
> +        size_t usecs = self->MinScriptRunTime() * PR_USEC_PER_SEC;

PRTime is 64-bit - make this int64_t, or a PRTime directly (with the cast below removed).
Attachment #8514481 - Flags: review?(bobbyholley) → review+
(Assignee)

Comment 10

4 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/09001e8ae611

I also ended up needing to modify an xpcshell test that assumed the interrupt handler would always be invoked once a second.
https://hg.mozilla.org/mozilla-central/rev/09001e8ae611
Status: NEW → RESOLVED
Last Resolved: 4 years ago
status-firefox36: affected → fixed
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
34 and 35 are marked as affected. Do you want to propose this for uplift?
Flags: needinfo?(bhackett1024)
(Assignee)

Comment 13

4 years ago
Comment on attachment 8514481 [details] [diff] [review]
patch

Approval Request Comment
[Feature/regressing bug #]: bug 976446
[User impact if declined]: regexps taking longer than one second to execute can end up taking much longer than is necessary
[Describe test coverage new/current, TBPL]: none
[Risks and why]: none
Flags: needinfo?(bhackett1024)
Attachment #8514481 - Flags: approval-mozilla-beta?
Attachment #8514481 - Flags: approval-mozilla-aurora?
Comment on attachment 8514481 [details] [diff] [review]
patch

Beta+
Aurora+
Attachment #8514481 - Flags: approval-mozilla-beta?
Attachment #8514481 - Flags: approval-mozilla-beta+
Attachment #8514481 - Flags: approval-mozilla-aurora?
Attachment #8514481 - Flags: approval-mozilla-aurora+
https://hg.mozilla.org/releases/mozilla-aurora/rev/1d4fe43b9a30
https://hg.mozilla.org/releases/mozilla-beta/rev/de49643707ae

Seems doubtful this would be taken for b2g32 (v2.0), but feel free to nominate it and make your case if you feel that it should be.
status-b2g-v2.2: affected → fixed
status-firefox34: affected → fixed
status-firefox35: affected → fixed

Updated

3 years ago
Depends on: 1183480
You need to log in before you can comment on or make changes to this bug.