Fix O(n^2) behavior in nsConsoleService::ClearMessagesForWindowID

RESOLVED FIXED in Firefox 42

Status

()

Core
XPCOM
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: khuey, Assigned: froydnj)

Tracking

({regression})

unspecified
mozilla43
regression
Points:
---

Firefox Tracking Flags

(firefox41 unaffected, firefox42+ fixed, firefox43 fixed)

Details

(URL)

Attachments

(1 attachment, 2 obsolete attachments)

Pretty classic O(n^2) array manipulation behavior there.
[Tracking Requested - why for this release]: We shouldn't ship this.
status-firefox41: --- → unaffected
status-firefox42: --- → affected
tracking-firefox42: --- → ?
The code that khuey's concerned about is (I think):
> 78   for (uint32_t i = 0; i < mBufferSize && mMessages[i]; i++) {
[...]
> 93     uint32_t j = i;
> 94     // Now shift all the following messages
> 95     for (; j < mBufferSize - 1 && mMessages[j + 1]; j++) {
> 96       mMessages[j] = mMessages[j + 1];
> 97     }
[...]
> 105     // Ensure the next iteration handles the messages we just shifted down
> 106     i--;
> 107   }

http://mxr.mozilla.org/mozilla-central/source/xpcom/base/nsConsoleService.cpp?mark=78-78,94-97&rev=49ae0961591e#78

This indeed looks like it has O(n^2) performance, and would blow up time-wise if we're clearing a nontrivial portion of mMessages.
Tracking for 42 since this is a regression (from bug 1185144 looks like)
tracking-firefox42: ? → +
(Assignee)

Comment 4

3 years ago
Created attachment 8648901 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

This ought to fix it.
Attachment #8648901 - Flags: review?(erahm)
(Assignee)

Updated

3 years ago
Assignee: nobody → nfroyd
(Side note: should we make mMessages use smart pointers, instead of manually-refcounted raw pointers? e.g. perhaps it should have type "nsCOMArray<nsIConsoleMessage>*" instead of "nsIConsoleMessage**"?

If this seems sane to people who are actually wrestling with this code, I'm happy to file a followup on it, but I'm mentioning it here, because it seems like any patch that tweaks this array [e.g. this bug's patch] will have a nontrivial chance of accidentally breaking the refcounting, as long as we're relying on manual macro invocations. froydnj, what do you think?)
Flags: needinfo?(nfroyd)
(er, I think I meant nsCOMArray<nsIConsoleMessage> actually -- not a pointer to a nsCOMArray.)
(Assignee)

Comment 7

3 years ago
I am a fan of writing safe code.  And yes, doing comment 6 would be preferable, too.
Flags: needinfo?(nfroyd)
(Cool, thanks. Filed bug 1195486 on converting mMessages to be safer then.)
Comment on attachment 8648901 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

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

Good news: Your approach looks good aside from a few corner cases.
Bad news: I think there's enough fundamentally wrong with nsConsoleService's attempt at a circular buffer that we'd be better off just replacing it.

A maximum sized LinkedList feels right here (O(1) insertFront, popLast, remove (when iterating)). We don't need random access, there are only 250 entries max so the overhead of a doubly-linked list is negligible, there is only one console service so no multiplier effect.

This would get rid of a fair amount of "handle the circular buffer thing" logic (which is currently wrong), in general the code would be easier to read, and it would inherently fix the problem we're try to solve here.

All of that said, I can just re-review w/ fixes for the corner cases and we can punt to the follow up.

::: xpcom/base/nsConsoleService.cpp
@@ +80,5 @@
> +  for (; i < mBufferSize && mMessages[i]; i++, openSlot++) {
> +    // Slide the message down if necessary.
> +    if (i != openSlot) {
> +      mMessages[openSlot] = mMessages[i];
> +      mMessages[i] = nullptr;

Corner cases: 
#1 - If we match all entries, mMessages[0] will not be nulled out
#2 - If we *only* match the last entry, it will not be nulled out

@@ +100,3 @@
>  
> +    // Compensate for incrementing openSlot in the loop header.
> +    openSlot--;

Is this always safe if |openSlot == 0|? I'm too lazy to spec spelunk this :)

@@ -105,1 @@
>      mFull = false;

Latent bug:

So this is just wrong. We're doing a circular buffer, by setting mFull to false we've effectively corrupted the proper order (element 0 is now the 'oldest' entry, mCurrent is the 'newest' + 1).
Attachment #8648901 - Flags: review?(erahm)
(Assignee)

Comment 10

3 years ago
(In reply to Eric Rahm [:erahm] from comment #9)
> This would get rid of a fair amount of "handle the circular buffer thing"
> logic (which is currently wrong), in general the code would be easier to
> read, and it would inherently fix the problem we're try to solve here.

Yeah, There are better data structures we could be using here, either rolling our own deque via a linked list or using another one.

> ::: xpcom/base/nsConsoleService.cpp
> @@ +80,5 @@
> > +  for (; i < mBufferSize && mMessages[i]; i++, openSlot++) {
> > +    // Slide the message down if necessary.
> > +    if (i != openSlot) {
> > +      mMessages[openSlot] = mMessages[i];
> > +      mMessages[i] = nullptr;
> 
> Corner cases: 
> #1 - If we match all entries, mMessages[0] will not be nulled out
> #2 - If we *only* match the last entry, it will not be nulled out

Does it make you feel any better to know that NS_RELEASE nulls out the pointer it frees?  I think that takes care of the corner cases here.

> @@ +100,3 @@
> >  
> > +    // Compensate for incrementing openSlot in the loop header.
> > +    openSlot--;
> 
> Is this always safe if |openSlot == 0|? I'm too lazy to spec spelunk this :)

Yes.  Arithmetic on unsigned types wraps like you would expect.  (Arithmetic that wraps on signed types is undefined behavior.)

> @@ -105,1 @@
> >      mFull = false;
> 
> Latent bug:
> 
> So this is just wrong. We're doing a circular buffer, by setting mFull to
> false we've effectively corrupted the proper order (element 0 is now the
> 'oldest' entry, mCurrent is the 'newest' + 1).

Wow, I just totally botched that review, then, didn't I?  Another reason to rewrite this code to make it clearer.  I'll fix that.
(Assignee)

Comment 11

3 years ago
Created attachment 8649339 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

Thank you for the thorough review!

This is the same patch, with the mFull bit deleted; I think the NS_RELEASE
nulling behavior takes care of your concerns about corner cases.
Attachment #8648901 - Attachment is obsolete: true
Attachment #8649339 - Flags: review?(erahm)
Comment on attachment 8649339 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

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

Oh! Good to know about NS_RELEASE nulling, so no concerns there. We still need to properly deal with |mFull| though.

::: xpcom/base/nsConsoleService.cpp
@@ +104,3 @@
>  
> +  if (openSlot != i) {
> +    mCurrent = openSlot;

Unfortunately we need to properly set mFull. It's used in various places to make decisions on how we access the backing array.

Really I think the easiest thing is to just rip out the circular buffer (this isn't hyperbole, the code would become much less tedious and our n^2 issue would be fixed).
Attachment #8649339 - Flags: review?(erahm)
(Assignee)

Comment 13

3 years ago
Created attachment 8649445 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

All right, the failures on try look to be intermittents and nothing completely
embarrassing, so here's the attempt at rewriting things to be less awful.
Attachment #8649339 - Attachment is obsolete: true
Attachment #8649445 - Flags: review?(erahm)
Comment on attachment 8649445 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

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

r=me Thank you for taking the time to do the proper fix.

::: xpcom/base/nsConsoleService.cpp
@@ +110,1 @@
>    }

Lets set mCurrentSize to zero here.

@@ +441,5 @@
>     */
>    MutexAutoLock lock(mLock);
>  
> +  ClearMessages();
> +  mCurrentSize = 0;

Can remove this if we move it to ClearMessages.
Attachment #8649445 - Flags: review?(erahm) → review+
(Assignee)

Comment 16

3 years ago
I am curious to know whether the additional memory allocations we're doing now have any effect...
https://hg.mozilla.org/mozilla-central/rev/0b69076d3bad
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox43: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla43
(Assignee)

Comment 18

3 years ago
Comment on attachment 8649445 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

Approval Request Comment
[Feature/regressing bug #]: bug 814497
[User impact if declined]: performance badness
[Describe test coverage new/current, TreeHerder]: I think we have tests for this.
[Risks and why]: Low risk.
[String/UUID change made/needed]: None.
Attachment #8649445 - Flags: approval-mozilla-aurora?
Comment on attachment 8649445 [details] [diff] [review]
fix quadratic behavior in nsConsoleService

Fix a bad performance regression, taking it.
Attachment #8649445 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
You need to log in before you can comment on or make changes to this bug.