Add/change metrics for cookie store loading:

Add/change metrics for cookie store loading:

Cookie.TimeLoad (previously the total time the IO thread was busy loading cookies) is now the sum of all DB-thread tasks for loading cookies.
Cookie.TimeBlockedOnLoad is the time between the IO thread requesting cookies to load and them finally being loaded.
Cookie.PriorityBlockingTime is the amount of time that there were one or more web requests waiting on cookies to load.
Cookie.PriorityLoadCount is the number of priority loads that occurred (i.e., different domains that were requested before the cookie store was fully loaded).

BUG=68657
TEST=


Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=109981

[erikwright (departed), 2011-11-11 20:19:17]

Hi Randy,

PTAL.

Thanks,

Erik

[Randy Smith (Not in Mondays), 2011-11-13 03:38:23]

There's a basic problem with these metrics which I'm not sure how to fix, which
is that they'll get seriously biased depending on the user's startup/shutdown
usage patterns.  I.e. user's that startup their browser at the beginning of the
day (or fire it up for a quick scan around the web and then shut it down until
they need it again) will be heavily overrepresented compared to users that leave
their browser up and running all the time (i.e. me :-}).  Maybe we can argue
that's ok, as the cost in loading for people who bounce the browser is higher
than people who just leave it running.  But I wanted to at least call the issue
out.

(The cookie monster deals with that same issue via the RecordPeriodicStats()
routine.  But scanning the code, it looks like I didn't do that for loading,
which I guess makes sense, sorta :-J).

Beyond that, looks good.  I've suggested some simplifications below you may or
may not want to take, but the only thing that I want to make sure is resolved
before you commit is the metrics_lock_; as I mention below, I don't understand
why we need it, and if we don't, I'd rather not have it (just document which
threads the various variables are used on).

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
File chrome/browser/net/sqlite_persistent_cookie_store.cc (right):

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:209: base::Lock
metrics_lock_;
Why do we need this lock?  All of the variables protected look like they're only
being accessed on the IO thread (LoadCookiesForKey, CompleteLoad*,
ReportMetrics).

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:221: bool
metrics_reporting_deferred_;
I think if you wanted to you could get rid of this without really compromising
the stats.  As I read the code, this will be set if you hit
CompleteLoadOnIOThread while there's still priority loads that have entered
LoadCookiesForKey but haven't exited CompleteLoadForKeyOnIOThread.  But if
that's the case, those priority loads will hit a null keys_to_load_ map, and
won't do anything.  You'll get the total_priority_requests_ bump (since that
happens at the same time as the num_priority_waiting_ increment), and not
including the contribution of that time on the DB thread won't effect your stats
much since it won't touch the database (if you take my other suggestion of just
instrumenting LoadCookiesForDomains, it won't affect your stats at all).  That
lets you get rid of this variable and the check & double call of
ReportMetrics(), which seems a win.  

I'll admit that the above reasoning is a bit complicated, but it still might be
worthwhile trying to assert on it rather than putting in code to handle
something that shouldn't happen.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:242: // The shortest lived
instances have no impact.
Nice idea!  I have to admit, the thing I'd really like is a class where the
delta got automatically incremented by the time that any IncrementTimeDelta's
pointing to it were alive (i.e. overlapping IncrementTimeDeltas working
properly, not just nested ones), but I don't think there's a way to provide that
functionality easily.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:243: class
IncrementTimeDelta {
Looking over this code, I think it would be simpler and (I believe--WDYT?) just
about accurate, if we just had a start/end timer in LoadCookiesForDomain--I
don't really believe that anything else could really take a lot of time (maybe
InitializeDatabase?).  I won't block you doing it this way, but I do wonder if
it's worth the extra code complexity.

[erikwright (departed), 2011-11-13 22:23:31]

Hi Randy,

I agree that there is a bit of a bias as you describe. I will look into the
periodic stats strategy but I think for this release, the goal is comparison to
previous metrics and it is actually therefore best to maintain the existing
bias.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
File chrome/browser/net/sqlite_persistent_cookie_store.cc (right):

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:209: base::Lock
metrics_lock_;
On 2011/11/13 03:38:23, rdsmith wrote:
> Why do we need this lock?  All of the variables protected look like they're
only
> being accessed on the IO thread (LoadCookiesForKey, CompleteLoad*,
> ReportMetrics).

Unfortunately, technically Load and LoadCookiesForKey are accessed on any
thread. The CookieMonster calls them on whichever thread it is accessed on
(though they immediately delegate to the DB thread).

I don't know if anyone calls the methods in question from the UI thread, but it
wouldn't be appropriate to assume they won't even if they don't now.

I thought about having the cookie monster always switch to the IO thread before
calling them, but it isn't aware of the IO thread (it would boil down to locking
to whichever thread the cookie monster were constructed on).

I could also have the SQLitePersistentCookieStore post a task to the IO thread,
in order to access the metrics and then post a task to the DB thread, but that
seems even worse than having the lock.

I chose to have a separate lock so that there would not be any contention with
the actual loading process.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:221: bool
metrics_reporting_deferred_;
On 2011/11/13 03:38:23, rdsmith wrote:
> I think if you wanted to you could get rid of this without really compromising
> the stats.  As I read the code, this will be set if you hit
> CompleteLoadOnIOThread while there's still priority loads that have entered
> LoadCookiesForKey but haven't exited CompleteLoadForKeyOnIOThread.  But if
> that's the case, those priority loads will hit a null keys_to_load_ map, and
> won't do anything.  You'll get the total_priority_requests_ bump (since that
> happens at the same time as the num_priority_waiting_ increment), and not
> including the contribution of that time on the DB thread won't effect your
stats
> much since it won't touch the database (if you take my other suggestion of
just
> instrumenting LoadCookiesForDomains, it won't affect your stats at all).  That
> lets you get rid of this variable and the check & double call of
> ReportMetrics(), which seems a win.  
> 
> I'll admit that the above reasoning is a bit complicated, but it still might
be
> worthwhile trying to assert on it rather than putting in code to handle
> something that shouldn't happen.

The race condition does not represent a bug, so asserting on it is not
appropriate. But it is unlikely, and presumably has a negligible impact on
accuracy of the histograms, so I'm happy to remove the deferral. I'll upload a
CL to that effect Monday AM or tonight if possible.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:242: // The shortest lived
instances have no impact.
On 2011/11/13 03:38:23, rdsmith wrote:
> Nice idea!  I have to admit, the thing I'd really like is a class where the
> delta got automatically incremented by the time that any IncrementTimeDelta's
> pointing to it were alive (i.e. overlapping IncrementTimeDeltas working
> properly, not just nested ones), but I don't think there's a way to provide
that
> functionality easily.

If there were other places looking for the same thing, it wouldn't be that hard,
but it isn't needed here.

If you point me at an opportunity for re-use I will do something with it, though
possibly in a separate commit. I took a quick look with the following query but
didn't find anything:

http://codesearch.google.com/codesearch#search/&exact_package=chromium&q=%5E%...

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:243: class
IncrementTimeDelta {
On 2011/11/13 03:38:23, rdsmith wrote:
> Looking over this code, I think it would be simpler and (I believe--WDYT?)
just
> about accurate, if we just had a start/end timer in LoadCookiesForDomain--I
> don't really believe that anything else could really take a lot of time (maybe
> InitializeDatabase?).  I won't block you doing it this way, but I do wonder if
> it's worth the extra code complexity.

Initialize DB is a significant cost, based on Hui's experiments. We saw it take
150ms out of 500ms total load times.

[erikwright (departed), 2011-11-14 15:56:26]

Hi Randy,

Please see my responses.

Thanks,

Erik

[Randy Smith (Not in Mondays), 2011-11-14 19:55:33]

LGTM.  If you decide to do the assertion below, I'd suggest running it back by
me again (as if I can't think of a good way to do it, I presume it's worth
reviewing how it's done :-}).  But you're welcome to commit what you have now.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
File chrome/browser/net/sqlite_persistent_cookie_store.cc (right):

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:209: base::Lock
metrics_lock_;
On 2011/11/13 22:23:31, erikwright wrote:
> On 2011/11/13 03:38:23, rdsmith wrote:
> > Why do we need this lock?  All of the variables protected look like they're
> only
> > being accessed on the IO thread (LoadCookiesForKey, CompleteLoad*,
> > ReportMetrics).
> 
> Unfortunately, technically Load and LoadCookiesForKey are accessed on any
> thread. The CookieMonster calls them on whichever thread it is accessed on
> (though they immediately delegate to the DB thread).
> 
> I don't know if anyone calls the methods in question from the UI thread, but
it
> wouldn't be appropriate to assume they won't even if they don't now.
> 
> I thought about having the cookie monster always switch to the IO thread
before
> calling them, but it isn't aware of the IO thread (it would boil down to
locking
> to whichever thread the cookie monster were constructed on).
> 
> I could also have the SQLitePersistentCookieStore post a task to the IO
thread,
> in order to access the metrics and then post a task to the DB thread, but that
> seems even worse than having the lock.
> 
> I chose to have a separate lock so that there would not be any contention with
> the actual loading process.

D'oh!  Good point.  If it's still in your plan to make the CookieMonster
non-thread safe at some point, I'd put a TODO() in to get rid of the lock. 
Beyond that, ok.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:221: bool
metrics_reporting_deferred_;
On 2011/11/13 22:23:31, erikwright wrote:
> On 2011/11/13 03:38:23, rdsmith wrote:
> > I think if you wanted to you could get rid of this without really
compromising
> > the stats.  As I read the code, this will be set if you hit
> > CompleteLoadOnIOThread while there's still priority loads that have entered
> > LoadCookiesForKey but haven't exited CompleteLoadForKeyOnIOThread.  But if
> > that's the case, those priority loads will hit a null keys_to_load_ map, and
> > won't do anything.  You'll get the total_priority_requests_ bump (since that
> > happens at the same time as the num_priority_waiting_ increment), and not
> > including the contribution of that time on the DB thread won't effect your
> stats
> > much since it won't touch the database (if you take my other suggestion of
> just
> > instrumenting LoadCookiesForDomains, it won't affect your stats at all). 
That
> > lets you get rid of this variable and the check & double call of
> > ReportMetrics(), which seems a win.  
> > 
> > I'll admit that the above reasoning is a bit complicated, but it still might
> be
> > worthwhile trying to assert on it rather than putting in code to handle
> > something that shouldn't happen.
> 
> The race condition does not represent a bug, so asserting on it is not
> appropriate. But it is unlikely, and presumably has a negligible impact on
> accuracy of the histograms, so I'm happy to remove the deferral. I'll upload a
> CL to that effect Monday AM or tonight if possible.

Why do you say it's not a bug?  I'm not saying it's a bug that a priority load
finishes after the regular load, I'm saying it's a bug (or a "can't happen") if
a priority load that finishes after the regular load loaded anything (==
contributed to the time spent loading).  A "can't happen" that would mess up our
statistics seems worth a DCHECK if we can figure out a way to do it, even if it
won't have any negative effect on user experience.  But that's IMO; I'm not
wedded to the idea.

Mind you, I can't come up with a good way to do the DCHECK(), so the point is
probably moot :-}.

http://codereview.chromium.org/8537016/diff/3001/chrome/browser/net/sqlite_pe...
chrome/browser/net/sqlite_persistent_cookie_store.cc:243: class
IncrementTimeDelta {
On 2011/11/13 22:23:31, erikwright wrote:
> On 2011/11/13 03:38:23, rdsmith wrote:
> > Looking over this code, I think it would be simpler and (I believe--WDYT?)
> just
> > about accurate, if we just had a start/end timer in LoadCookiesForDomain--I
> > don't really believe that anything else could really take a lot of time
(maybe
> > InitializeDatabase?).  I won't block you doing it this way, but I do wonder
if
> > it's worth the extra code complexity.
> 
> Initialize DB is a significant cost, based on Hui's experiments. We saw it
take
> 150ms out of 500ms total load times.

Completely fair; I'd just solve that by incrementing the appropriate counter
both there and in LoadCookiesForDomain, rather than the extra fanciness of the
possibly nested class.  Your call; just wanted to call out a possibly simpler
alternative.

[commit-bot: I haz the power, 2011-11-14 22:02:53]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/erikwright@chromium.org/8537016/7001

[commit-bot: I haz the power, 2011-11-14 23:54:28]

Change committed as 109981