637115 - NS_ERROR_STORAGE_BUSY when cloning places.sqlite

Status: RESOLVED FIXED

(Toolkit :: Places, defect)

Description

[Rich Walsh]

On a frequent but erratic basis, I get this JS error the first time I load a page:
Error: uncaught exception: [Exception... "Component returned failure code: 0x80630001 (NS_ERROR_STORAGE_BUSY) [mozIStorageConnection.clone]"  nsresult: "0x80630001 (NS_ERROR_STORAGE_BUSY)"  location: "JS frame :: resource://gre/components/nsPlacesAutoComplete.js :: <TOP_LEVEL> :: line 257"  data: no]

Loading a page with many links (e.g. a BBC News page) then takes several minutes as the code tries to clone the storage connection to places.sqlite 1200+ times.  When the error occurs, I see this sequence of events in mozStorageConnection:

  initialize:  open_v2 - srv= 0  mflags= 40006  file= places.sqlite

  Clone - pre init:  attempt= 1  flags=  40001  file= places.sqlite
  initialize:  open_v2 - srv= 0  mflags= 40001  file= places.sqlite
  Clone - post init: attempt= 1  rv= 0

  Clone - pre init:  attempt= 2  flags=  40001  file= places.sqlite
  initialize:  open_v2 - srv= 0  mflags= 40001  file= places.sqlite
  initialize:  step -    srv= 5
  Clone - post init: attempt= 2  rv= 80630001

  Clone - pre init:  attempt= 3  flags=  40001  file= places.sqlite
  initialize:  open_v2 - srv= 0  mflags= 40001  file= places.sqlite
  initialize:  prepare - srv= 5
  Clone - post init: attempt= 3  rv= 80630001
  [etc.]

After attempt number 3, every subsequent attempt also fails in sqlite3_prepare_v2().  When the error does not occur, all 3 clone attempts succeed and no further attempts are made.

The problem occurs regardless of whether I use a new profile or one whose places.sqlite is about 3mb.  I've rewritten a fair amount of the OS/2-specific code in sqlite3 (in particular, the mutex code) but that has had no effect.  I've also reverted to v3.73, again with no effect.

The only action that may have some effect is displaying the dropdown on the awesome bar before loading any page.  I don't recall seeing the problem occur after I've done so.

Comment 1

[Dave Yeo]

I believe Peter and AndyMac managed to get a wish.exe or tclsh.exe working good enough to run the sqlite3 test suite. Be nice to get that binary.

Comment 2

[Shawn Wilsher :sdwilsh]

Is WAL disabled on these connections?

Comment 3

[Rich Walsh]

(In reply to comment #2)
> Is WAL disabled on these connections?

The code I'm running has an explicit |#define SQLITE_OMIT_WAL 1| but it makes no difference.  (FYI... since we have no mmap(), we can't use the current implementation of WAL.)

Comment 4

[Shawn Wilsher :sdwilsh]

(In reply to comment #3)
> The code I'm running has an explicit |#define SQLITE_OMIT_WAL 1| but it makes
> no difference.  (FYI... since we have no mmap(), we can't use the current
> implementation of WAL.)
Right, but with WAL, readers don't block writers, and writers don't block readers.  What you folks are hitting on OS/2 is a reader (autocomplete code) being blocked be a writer (main places db).  That's why you are getting SQLITE_BUSY.

Comment 5

[Rich Walsh]

(In reply to comment #4)
> What you folks are hitting on OS/2 is a reader (autocomplete code)
> being blocked be a writer (main places db).  That's why you are getting
> SQLITE_BUSY.

OK.  But what do we do about it?  I thought WAL was supposed to affect performance, not functionality.

Comment 6

[Rich Walsh]

Some additional info:

My current FF session didn't encounter the problem I've described.  However, both autocomplete and the awesome bar's dropdown have stopped working (though they worked earlier).  places.sqlite-journal is updating as I load new pages and is now 425k but places.sqlite hasn't been written to in 3 hours (probably around the time I opened this session).

I believe the problem stems from some change made in mid to late December because I first mentioned it in an amail from Jan 2, and I know that a build from Dec 4 did not exhibit the problem.  I'll try to narrow the timeframe.

Comment 7

[Shawn Wilsher :sdwilsh]

(In reply to comment #5)
> OK.  But what do we do about it?  I thought WAL was supposed to affect
> performance, not functionality.
If affected performance because we could make architectural changes because of it.

(In reply to comment #6)
> My current FF session didn't encounter the problem I've described.  However,
> both autocomplete and the awesome bar's dropdown have stopped working (though
> they worked earlier).  places.sqlite-journal is updating as I load new pages
> and is now 425k but places.sqlite hasn't been written to in 3 hours (probably
> around the time I opened this session).
Sounds like you have an open transaction that isn't being closed.

> I believe the problem stems from some change made in mid to late December
> because I first mentioned it in an amail from Jan 2, and I know that a build
> from Dec 4 did not exhibit the problem.  I'll try to narrow the timeframe.
In that timeframe, we merged the Places branch to mozilla-central, which contained the change we made to enable WAL, among other things.

Comment 8

[Peter Weilbacher]

(In reply to comment #1)
> I believe Peter and AndyMac managed to get a wish.exe or tclsh.exe working good
> enough to run the sqlite3 test suite. Be nice to get that binary.

I sent the package to Rudi Ihle who was requesting it via PM.

(In reply to comment #7)
> (In reply to comment #5)
> > OK.  But what do we do about it?  I thought WAL was supposed to affect
> > performance, not functionality.
> If affected performance because we could make architectural changes because of
> it.

Looking at bug 573492 it seems that the final patch was never tested on OS/2, just some early version...

Comment 9

[Shawn Wilsher :sdwilsh]

After talking with drh, it looks like we can get a version of WAL that doesn't use shared memory.

Comment 10

[Rich Walsh]

(In reply to comment #9)
> After talking with drh, it looks like we can get a version of WAL that
> doesn't use shared memory.

If this entails the use of |PRAGMA locking_mode=EXCLUSIVE;| then it probably won't serve our needs.

I tried executing this immediately after opening places.sqlite for the first time and it did enter WAL mode (*-wal was created).  However, it locked out all of the subsequent cloned connections, regardless of whether the pragma was executed for them as well.  The result was no history of any sort and seemingly endless attempts to open a readonly connection.  (Another OS/2 developer tried this with his own app and had the same problem.)

Two things puzzle me:
- why is the problem intermittent?  The various connections appear to be opened in the same order each time, so it doesn't seem like a race condition.
- a write transaction's exclusive lock should only block readers for a finite period but here it seems to persist indefinitely.  Are we seeing some sort of deadlock?

Comment 11

[Ginn Chen]

PRAGMA locking_mode=EXCLUSIVE; only allows 1 connection.
heap memory WAL would allow multiple connections from multiple threads of 1 process.

Did you try the patch in Bug 633771 ?
Does it solve the problem on OS/2 ?

Comment 12

[Rich Walsh]

(In reply to comment #11)
> Did you try the patch in Bug 633771 ?
> Does it solve the problem on OS/2 ?

At first I thought it solved our _other_ problem (autocomplete fails, no dropdown from address bar) but that eventually started to happen.  It did nothing for the issue described above.

Comment 13

[Marco Bonardo [:mak]]

you cannot use EXCLUSIVE mode on places.sqlite

Comment 14

[Rich Walsh]

FYI... thanks to Rudi Ihle, OS/2 now has a working implementation of WAL.  If our testing goes well, I'll submit it upstream and close this bug in the near future.

Comment 15

[Shawn Wilsher :sdwilsh]

(In reply to comment #14)
> FYI... thanks to Rudi Ihle, OS/2 now has a working implementation of WAL.  If
> our testing goes well, I'll submit it upstream and close this bug in the near
> future.
That is awesome!

Comment 16

[Rich Walsh]

sqlite v3.7.6 includes OS/2's WAL implementation and it works without any known problems.  Closing this bug as resolved/fixed.