536544 - slow window.localStorage.setItem performance (on Windows)

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[bugzilla33]

User-Agent:       Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; InfoPath.2)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2b5) Gecko/20091204 Firefox/3.6b5


very slooooooooow webStorage, 2000 times setItem & getItem test:

Firefox 3.6 beta 5 (Win7x86): 94830ms
Opera 10.5.3172 (Win7x86): 140835ms

Chrome 4: 343ms
Safari 4: 3ms
IE 8: 102ms

Konqueror: (not supported)


Reproducible: Always

Steps to Reproduce:
1. open attachment
2 [review]. test it
Actual Results:  
94830ms

Expected Results:  
3ms like Safari 4.0.4

Comment 1

[bugzilla33]

Attachment: testcase

Comment 2

[(mostly gone) XtC4UaLL [:xtc4uall]]

dupe of/related to Bug 519907?

Comment 3

[bugzilla33]

no, Bug 519907 is MAC OS bug
this is Win7

Comment 4

[Honza Bambas (:mayhemer)]

So far not confirming but my experience is that reading/writing from/to the web storage is really slowest part if my web app, so I'll soon start working on this. I know about ways to make this really faster.

Comment 5

[bugzilla33]

Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2) Gecko/20100105
Firefox/3.6
Benchmark from attachment: 77ms on this machine.
Resolved Fixed.

Comment 6

[bugzilla33]

Sorry, I get this results only when run benchmark from local disk.

Comment 7

[bugzilla33]

Attachment: testcase

Comment 8

[bugzilla33]

Actual results:

Firefox 3.6: 104906ms
Chrome 4: 384ms
IE 8: 89ms
Opera 10.5.3296: 56ms
Safari 4: 2ms
Konqueror: (not supported)

Comment 9

[(mostly gone) XtC4UaLL [:xtc4uall]]

Minefield/3.7a5pre ID:20100503040502: 190833
Google Chrome 5.0.375.28: 737
Opera 10.53 Build 3374: 142

on WinxP SR3

Comment 10

[Boris Zbarsky [:bzbarsky]]

So the only way I can explain those numbers offhand (and in particular the fact that we're so much faster on non-Windows) is that storage is doing _something_ really slow with the filesystem...  Shawn, do you have any tools to measure that sort of thing?

Comment 11

[Boris Zbarsky [:bzbarsky]]

In particular, on Mac, where our performance is "only" 3x worse than chrome, the time breakdown is approximately:

37% mozilla::storage::Statement::Execute
11% mozilla::storage::Statement::ExecuteStep
8% mozilla::storage::Statement::Reset

Those are all called from nsDOMStoragePersistentDB::SetKey.  We also have:

13% mozilla::storage::Statement::ExecuteStep
4% mozilla::storage::Statement::Reset

The remaining 27% of the time is something like 5% nsDOMStorage::CanUseStorage, 5% getting the localStorage property off the Window, and various minor bits scattered about here and there; I can look into this in more details once we fix the hotspots).

My money is that on Windows the time under sqlite stuff here is through the roof for some reason.

Comment 12

[Boris Zbarsky [:bzbarsky]]

Poor-man's profiling with the debugger's pause button on Windows gives me the same stack each time.

kernel32.dll!7627c640()     
mozsqlite3.dll!winSync(sqlite3_file * id=0x064d2a20, int flags=2)  Line 27907 + 0xd bytes
mozsqlite3.dll!sqlite3OsSync(sqlite3_file * id=0x064d2a20, int flags=2)  Line 12099 + 0x12 bytes
mozsqlite3.dll!syncJournal(Pager * pPager=0x064d2900)  Line 34007 + 0x2a bytes	
mozsqlite3.dll!sqlite3PagerCommitPhaseOne(Pager * pPager=0x064d2900, const char * zMaster=0x00000000, int noSync=0)  Line 35884 + 0x9 bytes
mozsqlite3.dll!sqlite3BtreeCommitPhaseOne(Btree * p=0x065402c8, const char * zMaster=0x00000000)  Line 40544 + 0x11 bytes
mozsqlite3.dll!vdbeCommit(sqlite3 * db=0x04c192a8, Vdbe * p=0x064e74c0)  Line 48827 + 0xb bytes	C
mozsqlite3.dll!sqlite3VdbeHalt(Vdbe * p=0x064e74c0)  Line 49241 + 0xd bytes
mozsqlite3.dll!sqlite3VdbeExec(Vdbe * p=0x064e74c0)  Line 52970 + 0x9 bytes
mozsqlite3.dll!sqlite3Step(Vdbe * p=0x064e74c0)  Line 50603 + 0x9 bytes
mozsqlite3.dll!sqlite3_step(sqlite3_stmt * pStmt=0x064e74c0)  Line 50664 + 0x9 bytes
xul.dll!mozilla::storage::Statement::ExecuteStep(int * _moreResults=0x004bb04c)  Line 729 + 0xc bytes

As expected, we're syncing for some reason.  Is that a bug in the DOM use of storage here, in storage, or in sqlite?

Note: winSync calls FlushFileBuffers.  The docs for this say:

  Due to disk caching interactions within the system, the FlushFileBuffers
  function can be inefficient when used after every write to a disk drive
  device when many writes are being performed separately. If an application is
  performing multiple writes to disk and also needs to ensure critical data is
  written to persistent media, the application should use unbuffered I/O
  instead of frequently calling FlushFileBuffers.

Doesn't sound like a function we want to be calling on each ExecuteStep()!

Comment 13

[Shawn Wilsher :sdwilsh]

(In reply to comment #12)
> As expected, we're syncing for some reason.  Is that a bug in the DOM use of
> storage here, in storage, or in sqlite?
I don't know this code in particular, but it should really really use transactions if you are doing lots of writes.  That will avoid the fsync after every insert/update.

Comment 14

[Boris Zbarsky [:bzbarsky]]

So the query that seems to trigger those syncs here is:

246          NS_LITERAL_CSTRING("UPDATE webappsstore2 "
247                             "SET value = ?1, secure = ?2"
248                             "WHERE scope = ?3 "
249                             "AND key = ?4"),

It's executed once per key set, more or less.  Since key sets are completely under the control of the page JS, a transaction would only contain a single update query like that, right?  Would that actually help?

If individual sqlite updates are just expensive, then it seems like sqlite is the wrong backend for DOM Storage in general, or there needs to be an in-memory cache sitting in front of it or something....

Comment 15

[Shawn Wilsher :sdwilsh]

(In reply to comment #14)
> So the query that seems to trigger those syncs here is:
Hopefully that query is cached and not created every time...

> It's executed once per key set, more or less.  Since key sets are completely
> under the control of the page JS, a transaction would only contain a single
> update query like that, right?  Would that actually help?
In that case, no...it's still going to fsync twice every set which sucks.

> If individual sqlite updates are just expensive, then it seems like sqlite is
> the wrong backend for DOM Storage in general, or there needs to be an in-memory
> cache sitting in front of it or something....
We could set synchronous = OFF (http://www.sqlite.org/pragma.html#pragma_synchronous).

Comment 16

[Honza Bambas (:mayhemer)]

Shawn, if I remember correctly it's not that long we talked about moving I/O from the main thread to the background.  Part of it should be moving the persistent DB operations for dom storage as well.  We were talking about using the in-memory DB we already have an implementation for instead of persistent DB directly and store from the memory to disk in background.  Do you plan to do this?  It would perfectly fix this bug IMO.

Comment 17

[Boris Zbarsky [:bzbarsky]]

> Hopefully that query is cached and not created every time...

Looks like it to me, yes.

> We could set synchronous = OFF

That seems like a reasonable approach to me, given the "best-effort" nature of web storage, no?  Esp. if we can recover from a corrupt database?  Is this something we could do on branches?

Comment 16 sounds like the "in-memory cache" I mention; it would indeed fix this bug.  It definitely sounds trunk-only, though, and even then not clear that it would happen for 1.9.3...

Comment 18

[Shawn Wilsher :sdwilsh]

(In reply to comment #16)
> Shawn, if I remember correctly it's not that long we talked about moving I/O
> from the main thread to the background.  Part of it should be moving the
> persistent DB operations for dom storage as well.  We were talking about using
> the in-memory DB we already have an implementation for instead of persistent DB
> directly and store from the memory to disk in background.  Do you plan to do
> this?  It would perfectly fix this bug IMO.
I think that that was mak you were talking to, not me.

(In reply to comment #17)
> That seems like a reasonable approach to me, given the "best-effort" nature of
> web storage, no?  Esp. if we can recover from a corrupt database?  Is this
> something we could do on branches?
Well, recover from a corrupt database is "nuke it".  If you get SQLITE_CANTOPEN back, you can't do anything.

Comment 19

[Boris Zbarsky [:bzbarsky]]

> Well, recover from a corrupt database is "nuke it".

Which might be fine if actual corruption on synchronous = OFF is rare...  Someone more familiar with both what DOMStorage promises and what mysql's behavior is should make that call.

Comment 20

[Boris Zbarsky [:bzbarsky]]

I mean sqlite, of course, not mysql... ;)

Comment 21

[Shawn Wilsher :sdwilsh]

(In reply to comment #19)
> Which might be fine if actual corruption on synchronous = OFF is rare... 
> Someone more familiar with both what DOMStorage promises and what mysql's
> behavior is should make that call.
It should be rare, but we saw more corruption with it off.  I guess rare with hundreds of millions of users can still equate to lots of people getting corruption.

Comment 22

[Boris Zbarsky [:bzbarsky]]

Sure; the question is whether it's rare enough for any given user to satisfy whatever guarantees about data persistence localStorage provides.

Comment 23

[Johnny Stenback (:jst)]

Given the size of the performance gap here, I'm marking this a blocker for 1.9.3 final.

Comment 24

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Don't Chrome and Webkit use SQLite for localStorage? What do they do?

Comment 25

[Honza Bambas (:mayhemer)]

I'll look what we can do with this.

Comment 26

[Honza Bambas (:mayhemer)]

The system now does following when setting an item on a persistent storage:
- if current usage (the amount of data already stored for a domain) is not cached, do a relatively expensive select and cache the usage amount value ; we do this to check quota
- select the key and value from the database to see if it is already present
- if it does exist, check the 'secret' value (this probably might be bypassed, as we use this only for sessionStorage and it is not ever persisted) to disallow http pages see/change what https pages have stored
- then we do INSERT OR REPLACE if the entry is not present in the database (note the REPLACE here even if it is not needed)
- or we do UPDATE if it is present

I checked that we correctly use indexes during update.

The bottleneck here are the INSERT and UPDATE.  Those are both very slow because we:
a) use sync database store
b) we are not using transactions when doing a lot of inserts/updates in a line

Any in-memory caching is useless here, sqlite does caching for us, and we select using a proper index. Tests also show:
100x setItem, each entry a new record, while usage select and item existence select bypassed (commented out), using just INSERT: ~1450ms
100x setItem, each entry an existing record (all previous values update), service code also commented out, using UPDATE: ~1700ms
100x getItem, code unchanged, using SELECT: ~32ms

While using just INSERT OR REPLACE, service code commented out:
100x setItem new: ~1450ms
100x setItem update: ~2100ms
100x getItem: ~30ms


We probably won't ever build sqlite with nosync, so I want to wrap INSERT OR REPLACE INTO to a transaction, that gets committed when we do a different op or simply after some time (using timer, say 10 seconds).  There is no need to fetch the old value and the secret flag.  We can cache all the keys in a hash table, it is extremely fast to do that, and check quota using that hash table data.

Comment 27

[Boris Zbarsky [:bzbarsky]]

Is sync vs nosync a build-time setting for sqlite, or a per-database setting?

Comment 28

[Honza Bambas (:mayhemer)]

(In reply to comment #27)
> Is sync vs nosync a build-time setting for sqlite, or a per-database setting?

I guess build time, there is no setting for 'async' during db open.

Comment 29

[Honza Bambas (:mayhemer)]

Attachment: v1

- all INSERTs (setItem) are wrapped to a transaction
- this transaction is committed whenever we do a different operation
- transaction is committed every 5 seconds otherwise, takes 3-5ms to complete
- items are properly cached in memory now
- all test known to me touching dom storage are passing

With this patch I get these numbers:
100x setItem new: ~70ms
100x setItem update: ~50ms
100x getItem: ~30ms

So it is about 3000% better performance then before.  To really get this performance gain a web app must ensure not to call to any getItem, length and other methods of localStorage between all setItems it wants to do.

Comment 30

[Shawn Wilsher :sdwilsh]

What exactly does nosync do?  Is it the same as PRAGMA synchronous = OFF? (http://www.sqlite.org/pragma.html#pragma_synchronous)

(In reply to comment #26)
> Any in-memory caching is useless here, sqlite does caching for us, and we
> select using a proper index. Tests also show:
This isn't the right kind of in-memory cache we want to do here.  What we should do is store all data for a domain in a temporary table.  Every so often, we'd have to flush changes from this table into the on-disk table.  We could even do this asynchronous with the async storage API so we end up removing the writes on the main thread for localStorage.

Comment 31

[Honza Bambas (:mayhemer)]

(In reply to comment #30)
> What exactly does nosync do?  Is it the same as PRAGMA synchronous = OFF?
> (http://www.sqlite.org/pragma.html#pragma_synchronous)

With it I got (my patch took off the tree):
100x setItem new: ~350ms
100x setItem update: ~350ms
100x getItem: ~20ms

I'll try to code the temp table and see if we get more perf gain here.  Good idea, btw.

Comment 32

[Shawn Wilsher :sdwilsh]

(In reply to comment #31)
> I'll try to code the temp table and see if we get more perf gain here.  Good
> idea, btw.
We use it in places.  See nsPlacesDBFlush.js for some real-world code samples.

Comment 33

[Honza Bambas (:mayhemer)]

So, as this is a blocking bug, I want to do as few changes as needed to keep it minimal and scoped to this bug (i.e. to only make inserts/updates rapidly faster).  I would go this way:

- at the moment we first want to access the storage data copy all rows for the scope (domain or origin) to a temp in-memory table
- do all storage operations bound to that scope on that table (i.e. selects, usage count, inserts)
- from time to time do a flush of that table + delete its content
- return to the first step

Shawn, is that ok?

Based on this, we can remove a lot of code like items and usage caching and clean the storage code up a bit with it.  But it is not part of this bug.

Also the temp table could potentially be used for private browsing and session-only storage, only never flushed to the disk table.  But now I'm just throwing thoughts.

Comment 34

[Shawn Wilsher :sdwilsh]

(In reply to comment #33)
> Shawn, is that ok?
Yes

> Also the temp table could potentially be used for private browsing and
> session-only storage, only never flushed to the disk table.  But now I'm just
> throwing thoughts.
That is sorta what we do in places :)

That can happen post firefox 4 though too.

Comment 35

[Honza Bambas (:mayhemer)]

Attachment: v2

Shawn, can you take a look please?  So far thanks for all your guidance on this.

This patch is:
- using the same approach as the places do, having the view and temp table, altering deletion on the view
- insert/replaces are bound to a transaction
- the temporary table is flushed when no change has been made for 5 seconds or it is older then 30 seconds after load, or simply on profile change or shutdown
- I didn't implement the flush as async query, I believe this is enough to go and I want as low-risk patch as possible (that this one starts not to be..)

Test numbers:
100x setItem new: ~35ms
100x setItem update: ~35ms
100x getItem: ~20ms

So, even better then before.

Pushing to try server, tests locally passing.

Comment 36

[Honza Bambas (:mayhemer)]

Passed try server.

Comment 37

[Honza Bambas (:mayhemer)]

And the try server build for testing the new super-fast speed is available at:

http://ftp.mozilla.org/pub/mozilla.org/firefox/tryserver-builds/[e-mail]-0d54fd5eec48

Comment 38

[Shawn Wilsher :sdwilsh]

Is late this week or early next week too late for me to look at this?

Comment 39

[Honza Bambas (:mayhemer)]

This is Fx4 blocker, I really would love to get this in, so the earlier the better.  I'll try to find someone else, if I won't, I'll leave the review assigned to you.

Comment 40

[Shawn Wilsher :sdwilsh]

(In reply to comment #39)
> This is Fx4 blocker, I really would love to get this in, so the earlier the
> better.  I'll try to find someone else, if I won't, I'll leave the review
> assigned to you.
Yeah, I have some other blocker reviews too (some betaN ones which take priority over this) plus my own blockers, hence the delay.  Prioritization is hard :(

But, this is a blocker, so it does have priority over non-blockers.

Comment 41

[Shawn Wilsher :sdwilsh]

Comment on attachment 476881 [details] [diff] [review]
v2

>+++ b/dom/src/storage/nsDOMStorage.cpp
>+  } else if (!strcmp(aTopic, "timer-callback")) {
>+    nsCOMPtr<nsIObserverService> obsserv = mozilla::services::GetObserverService();
>+    obsserv->NotifyObservers(nsnull, NS_DOMSTORAGE_FLUSH_TIMER_OBSERVER, nsnull);
I've never not seen us check that obsserv is non-null.  Please check here.

> nsDOMStorage::SetItem(const nsAString& aKey, const nsAString& aData)
> {
You use IsCallerSecure in up to two places in this method.  We should cache that result since it's not a trivial method.

>+  // If we are not forced to flush (e.g. on shutdown) then don't flush if the
>+  // last table access is less then 5 seconds ago or the table itself is not
>+  // older then 30 secs
>+  if (!force &&
>+      _EPOCH_IS_LESS_THEN(mLastTemporaryTableAccessTime, 5000) &&
>+      _EPOCH_IS_LESS_THEN(mTemporaryTableAge, 30000))
please use constants instead of magic numbers (even if there is a comment)

>+NS_IMETHODIMP
>+nsDOMStorage::Observe(nsISupports *subject,
>+                      const char *topic,
>+                      const PRUnichar *data)
>+{
>+  PRBool isProfileBeforeChange = !strcmp(topic, "profile-before-change");
>+  PRBool isXPCOMShutdown = !strcmp(topic, NS_XPCOM_SHUTDOWN_OBSERVER_ID);
>+  PRBool isFlushTimer = !strcmp(topic, NS_DOMSTORAGE_FLUSH_TIMER_OBSERVER);
just use bool

>+  rv = mConnection->ExecuteSimpleSQL(NS_LITERAL_CSTRING(
>+        "PRAGMA journal_mode = MEMORY"));
>+  NS_ENSURE_SUCCESS(rv, rv);
I don't think you want to do this.  If we crash while writing, we'll end up with a corrupted database.

>+  // temporary - disk synchronization statements
>+  rv = mConnection->CreateStatement(NS_LITERAL_CSTRING(
>+         "INSERT INTO webappsstore2_temp"
>+         " SELECT * FROM webappsstore2"
>+         " WHERE scope = ?1 AND NOT EXISTS ("
>+            "SELECT scope, key FROM webappsstore2_temp "
>+            "WHERE scope = webappsstore2.scope AND key = webappsstore2.key)"),
>+         getter_AddRefs(mCopyToTempTableStatement));
>+  NS_ENSURE_SUCCESS(rv, rv);
In general, it's better to use named parameters and then BindByName on them instead of BindByIndex.

>@@ -569,34 +716,39 @@ nsDOMStoragePersistentDB::RemoveOwners(c
>     expression.AppendLiteral(
>-      "SELECT DISTINCT scope FROM webappsstore2 WHERE scope GLOB ?");
>+      "SELECT DISTINCT scope FROM webappsstore2_view WHERE scope GLOB ?");
SELECTing from a view is slow because it does not use indexes.  You'll want to do a join here and use the indexes in the temp and on disk tables.

r=sdwilsh, but I'd feel a lot better about this if someone more familiar with this code also took a look at it.

Comment 42

[Honza Bambas (:mayhemer)]

(In reply to comment #41)

Thanks for this review.

> >-      "SELECT DISTINCT scope FROM webappsstore2 WHERE scope GLOB ?");
> >+      "SELECT DISTINCT scope FROM webappsstore2_view WHERE scope GLOB ?");
> SELECTing from a view is slow because it does not use indexes.  You'll want to
> do a join here and use the indexes in the temp and on disk tables.

Is it just this one statement or should I check all other doing something with the view?  I confirmed with explain that the view select is using indexes on both tables.

> 
> r=sdwilsh, but I'd feel a lot better about this if someone more familiar with
> this code also took a look at it.

Jst?

Comment 43

[Shawn Wilsher :sdwilsh]

(In reply to comment #42)
> Is it just this one statement or should I check all other doing something with
> the view?  I confirmed with explain that the view select is using indexes on
> both tables.
I think I only saw DELETEs and this one SELECT, so I think you are OK as long as this one gets fixed.  But it doesn't hurt to double check.  The DELETEs are OK because you have the INSTEADOF DELETE trigger.

> Jst?
Whoever you usually have review changes to this code is fine.

Comment 44

[Honza Bambas (:mayhemer)]

Shawn, what about to turn this code:

  for (PRUint32 i = 0; i < aOwners.Length(); i++) {
    if (i)
      expression.AppendLiteral(" UNION ");

    expression.AppendLiteral(
      "SELECT DISTINCT scope FROM webappsstore2_view WHERE scope GLOB ?");
  }
  expression.AppendLiteral(");");

...to this code:

  for (PRUint32 i = 0; i < aOwners.Length(); i++) {
    if (i)
      expression.AppendLiteral(" UNION ");

    expression.AppendLiteral(
      "SELECT DISTINCT scope FROM webappsstore2 WHERE scope GLOB ?");
    expression.AppendLiteral(" UNION ");
    expression.AppendLiteral(
      "SELECT DISTINCT scope FROM webappsstore2_temp WHERE scope GLOB ?");
  }
  expression.AppendLiteral(");");

...?

Comment 45

[Shawn Wilsher :sdwilsh]

(In reply to comment #44)
>     expression.AppendLiteral(
>       "SELECT DISTINCT scope FROM webappsstore2 WHERE scope GLOB ?");
>     expression.AppendLiteral(" UNION ");
>     expression.AppendLiteral(
>       "SELECT DISTINCT scope FROM webappsstore2_temp WHERE scope GLOB ?");
You might be better off with a subselect here that looks like this:
SELECT DISTINCT FROM (
  SELECT scope
  FROM webappsstore2
  WHERE scope GLOB ?
  UNION
  SELECT scope
  FROM webappsstore_temp
  WHERE scope GLOB ?
)

Check and see which one performs better and go with it.

Comment 46

[Honza Bambas (:mayhemer)]

Your suggested statement has a more complex pseudo code and does one more pass through the result.  What I suggest is doing the distinction (that prevents the index from being used) by the UNION keyword.

Comment 47

[Honza Bambas (:mayhemer)]

Attachment: v2.1 [Check in comment 52]

Updated patch to review comments + improved usage sum statement.

Comment 48

[Honza Bambas (:mayhemer)]

Attachment: idiff v2 - v2.1

Comment 49

[Sheila Mooney]

Hey guys, what's the next step for this bug?

Comment 50

[Boris Zbarsky [:bzbarsky]]

The next step is jst doing the review.  Which will likely happen once he's not working on beta7 blockers.

Comment 51

[Johnny Stenback (:jst)]

Comment on attachment 478814 [details] [diff] [review]
v2.1 [Check in comment 52]

- In class nsDOMStorage:

+  PRIntervalTime mLastTemporaryTableAccessTime;
+  PRIntervalTime mTemporaryTableAge;

Could you use mozilla::TimeStamp here? Seems you could clean up the code in MaybeCommitTemporaryTable() a bit if you did.

sr=jst, preferably with the above suggested change.

Comment 52

[Honza Bambas (:mayhemer)]

Comment on attachment 478814 [details] [diff] [review]
v2.1 [Check in comment 52]

http://hg.mozilla.org/mozilla-central/rev/cdef53b45c9c