802920 - Gather additional Telemetry on performance of LocalStorage operations

Status: RESOLVED FIXED

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

Description

[Vladan Djeric (:vladan)]

Attachment: Add timers for common LocalStorage operations

I am currently refactoring LocalStorage to make it asynchronous, so we'll need performance data from before and after the change

This patch adds timing to 5 LocalStorage operations: GetAllKeys, GetKeyValue, SetKey, RemoveKey, and clear all LocalStorage. 

I also deleted histograms related to the removed GlobalStorage functionality. Is it a problem for Metrics scripts if an obsolete histogram is removed form Histograms.json?

Comment 1

[(dormant account)]

Comment on attachment 672634 [details] [diff] [review]
Add timers for common LocalStorage operations

I'm not sure these are interesting, these are usually 0. Would be more interesting to time cold cache case in http://mxr.mozilla.org/mozilla-central/source/dom/src/storage/nsDOMStoragePersistentDB.cpp#226

+ commit-to-disk times.

Comment 2

[(dormant account)]

Removing histogram definitions is not a problem and is encouraged

Comment 3

[Vladan Djeric (:vladan)]

(In reply to Taras Glek (:taras) from comment #1)
> I'm not sure these are interesting, these are usually 0. 

I went back and forth on this when I wrote the patch. It's true that most LocalStorage ops will be < 1ms because the domain's data has already been fetched in an earlier operation, but they won't all be 0. The new measurements will give us a chance to quantify the improvements from the new approach. For example (*made up numbers*): average "GetKeyValue" operations used to have 15% of reads take at least 1ms with such reads having an average of 15 ms in the old code vs new code where only 5% of "GetKeyValues" take at least 1ms (e.g. because of pre-fetching) and average is 12ms

> Would be more interesting to time cold cache case in
> http://mxr.mozilla.org/mozilla-central/source/dom/src/storage/
> nsDOMStoragePersistentDB.cpp#226
> 
> + commit-to-disk times.

We can add these but we do already track LocalStorage DB write & read times with MOZ_SQLITE_WEBAPPS_(WRITE|READ|SYNC)_MAIN_THREAD_MS and number of bytes written/read in MOZ_SQLITE_WEBAPPS_(WRITE|READ)_B

Comment 4

[(dormant account)]

(In reply to Vladan Djeric (:vladan) from comment #3)
> (In reply to Taras Glek (:taras) from comment #1)
> > I'm not sure these are interesting, these are usually 0. 
> 
> I went back and forth on this when I wrote the patch. It's true that most
> LocalStorage ops will be < 1ms because the domain's data has already been
> fetched in an earlier operation, but they won't all be 0. The new
> measurements will give us a chance to quantify the improvements from the new
> approach. For example (*made up numbers*): average "GetKeyValue" operations
> used to have 15% of reads take at least 1ms with such reads having an
> average of 15 ms in the old code vs new code where only 5% of "GetKeyValues"
> take at least 1ms (e.g. because of pre-fetching) and average is 12ms

We know where the bottleneck is and we should focus on it, ie reads/writes. I don't see why we'd benefit from measuring functioncall+memory read overhead in milliseconds with some occasional IO mixed in. 

> 
> > Would be more interesting to time cold cache case in
> > http://mxr.mozilla.org/mozilla-central/source/dom/src/storage/
> > nsDOMStoragePersistentDB.cpp#226
> > 
> > + commit-to-disk times.
> 
> We can add these but we do already track LocalStorage DB write & read times
> with MOZ_SQLITE_WEBAPPS_(WRITE|READ|SYNC)_MAIN_THREAD_MS and number of bytes
> written/read in MOZ_SQLITE_WEBAPPS_(WRITE|READ)_B
Those are going away...and they will not help for comparing perf once your new non-sql code lands.

Comment 5

[Vladan Djeric (:vladan)]

Attachment: Add timers for common LocalStorage operations, v2

Added 3 new histograms:

1) Time to fetch domain data on a cold cache
2) Time to flush dirty lines
#) Time to fetch quota use information (done on main thread)

Comment 6

[(dormant account)]

Comment on attachment 674112 [details] [diff] [review]
Add timers for common LocalStorage operations, v2

+  nsCOMPtr<mozIStorageStatement> stmt =
+    mStatements.GetCachedStatement(
+      "SELECT COUNT(*) FROM webappsstore2_temp WHERE modified = 1"
+    );
+  mozStorageStatementScoper scope(stmt);
+
+  TimeStamp startTime;
+  bool exists;
+  int32_t dirtyCount;
+  if (stmt &&
+      NS_SUCCEEDED(stmt->ExecuteStep(&exists)) && exists &&
+      NS_SUCCEEDED(stmt->GetInt32(0, &dirtyCount)) && dirtyCount > 0) {
+    // Time the operation if dirty entries will be flushed
+    startTime = TimeStamp::Now();
+  }
+

This is such a mess. But I don't have a better idea here. Maybe mak has a suggestion.

Comment 7

[Marco Bonardo [:mak]]

Comment on attachment 674112 [details] [diff] [review]
Add timers for common LocalStorage operations, v2

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

(In reply to Taras Glek (:taras) from comment #6)
> This is such a mess. But I don't have a better idea here. Maybe mak has a
> suggestion.

I don't like it as well, but there's no other way to count flushed entries, the trigger exists exactly to avoid the need to select them... the only alternative could be to take the timediff regardless, but report it only if > than a threshold, ideally if there's nothing to flush it will take almost no time, while if there are entries it will take some time... so you could experiment with thresholds and see what could make sense (>30ms?)

Btw, I'd be interested in knowing which kind of approach will be taken to make LS async, are you using my patch as a starting point or a completely new approach? (since I read something about non-SQL)

Comment 8

[Vladan Djeric (:vladan)]

(1:34:22 PM) taras: vladan: so i was thinking about 802920
(1:34:28 PM) taras: instead of running sql
(1:34:36 PM) taras: we should just time it and only report it if it's >1ms
(1:42:59 PM) taras: ie what mak suggested
taras ttaubert 
(1:45:37 PM) vladan: taras: ok but that's gonna skew results
(1:46:32 PM) vladan: i.e. an implementaiton where 99% of access < 1ms might have higher average time than an implementation where 1% of access times < 1ms
(1:46:50 PM) taras: i know
(1:47:02 PM) taras: but real io cant happen in <1ms
(1:47:18 PM) taras: i dunno
(1:47:23 PM) taras: vladan: this wasn't an order
(1:47:26 PM) taras: just a thought
(1:47:32 PM) taras: i've r+ed this 
(1:47:37 PM) taras: so it's up to you
(1:47:45 PM) taras: i don't like it either way
(1:48:16 PM) vladan: what's the objection to doing the SELECT on the temporary table? just that the code is fugly?
(1:48:27 PM) taras: yeah
(1:48:29 PM) taras: pointless overhead
(1:48:42 PM) taras: and ugly
(1:48:44 PM) taras: but it's cheap
(1:48:45 PM) taras: and contained
(1:48:51 PM) taras: so  i dont have strong feelings against it
(1:49:13 PM) vladan: the ugly code is not gonna make it out of the current nightly
(1:49:30 PM) taras: vladan: ok sold :)

Comment 9

[Vladan Djeric (:vladan)]

Comment on attachment 674112 [details] [diff] [review]
Add timers for common LocalStorage operations, v2

https://hg.mozilla.org/integration/mozilla-inbound/rev/b3c8f279987b

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b3c8f279987b

Comment 11

[Marco Bonardo [:mak]]

fwiw, imo we care more about how bad flushes may be, than how many users are affected by bad flushes. Btw, whatever, the overhead should not be high considered it's memory.

Comment 12

[(dormant account)]

Comment on attachment 674112 [details] [diff] [review]
Add timers for common LocalStorage operations, v2

not sure why this was still r?