Closed Bug 1091459 Opened 5 years ago Closed 5 years ago

Regexp performance issue


(Core :: JavaScript Engine, defect)

33 Branch
Not set



Tracking Status
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


(Reporter: pierre, Assigned: bhackett)



(Keywords: regression)


(2 files)

Attached file 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:

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.
Depends on: 1084280
OS: Linux → All
Hardware: x86_64 → All
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
Ever confirmed: true
Keywords: regression
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
Attached patch patchSplinter Review
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)
It now takes ~2300ms with the patch, quite the same as in Chrome. Thanks Brian!
Comment on attachment 8514481 [details] [diff] [review]

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

Looks like std::min is OK to use in our codebase at this point, yay.
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.
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]

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+

I also ended up needing to modify an xpcshell test that assumed the interrupt handler would always be invoked once a second.
Closed: 5 years ago
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)
Comment on attachment 8514481 [details] [diff] [review]

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]

Attachment #8514481 - Flags: approval-mozilla-beta?
Attachment #8514481 - Flags: approval-mozilla-beta+
Attachment #8514481 - Flags: approval-mozilla-aurora?
Attachment #8514481 - Flags: approval-mozilla-aurora+

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.
Depends on: 1183480
You need to log in before you can comment on or make changes to this bug.