[sql] Stats gathering for sql/ APIs.

[sql] Stats gathering for sql/ APIs.

Generate stats for how many SQL statements are executed, how many
results they return, and how many changes they make.  Generate timing
values for how long is spent doing all queries, doing updating
operations, doing autocommit updates, and commiting transactions.

The goal of these metrics is to quantify results of decisions like
enabling write-ahead log or memory-mapped I/O.

BUG=489788, 489444
Committed: https://crrev.com/58b8df8572e25ff91b3073213651aed4ebd675b5
Cr-Commit-Position: refs/heads/master@{#332503}

[Scott Hess - ex-Googler, 2015-05-19 23:57:49]

shess@chromium.org changed reviewers:
+ rmcilroy@chromium.org

[Scott Hess - ex-Googler, 2015-05-19 23:57:49]

I've been meaning to land a couple stats-related CLs to inform enabling mmap
mode, so I randomly picked you out, since everyone in sql/OWNERS is there under
duress.  Let me know if this is onerous.

I've addressed the trybot breakage locally, but my box is currently running very
slowly and I need to head out.  I've posted the patch, but AFAICT none of the
breaks are really core issues with the CL.

[rmcilroy, 2015-05-21 22:54:48]

Looks pretty good, a couple of suggestions.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.cc
File sql/connection.cc (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.cc#newco...
sql/connection.cc:1029: base::HistogramBase::kUmaTargetedHistogramFlag);
Maybe make a helper function which creates a Medium times histogram with a given
name to avoid repeating the same parameters each time here.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h
File sql/connection.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcode40
sql/connection.h:40: }
AFAIK friended classes don't need to be declared (they are forward declared on
the spot in the friend declaration)

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcod...
sql/connection.h:595: void CommitTime(const base::TimeDelta& delta);
I think it would be clearer with "Record" prefixed to each of these function
names.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcod...
sql/connection.h:616: void ChangeHelper(const base::TimeDelta& delta, bool
read_only);
nit - maybe RecordTimeAndChangesHelper?

https://codereview.chromium.org/1145833002/diff/20001/sql/proxy.h
File sql/proxy.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/proxy.h#newcode15
sql/proxy.h:15: // issue.
nit - mention this is just required for tests (assuming this is the case).

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc
File sql/statement.cc (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc#newcode61
sql/statement.cc:61: const base::TimeTicks before = base::TimeTicks::Now();
You should probably only call base::TimerTicks::Now() if timer_flag is true and
you are going to use the result - it can be costly on some platforms.

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h
File sql/statement.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h#newcode180
sql/statement.h:180: // the results.  The checked value from sqlite3_step() is
returned.
"and histograms based on the results if |timer_flag| is true."

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h#newcode181
sql/statement.h:181: int InnerStep(bool timer_flag);
Maybe call StepInternal would be clearer?

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:40004: +<histogram
name="Sqlite.AutoCommitTime" units="milliseconds">
Do you need to list the tagged versions too?

[Scott Hess - ex-Googler, 2015-05-21 23:42:37]

Thanks much for the feedback!

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.cc
File sql/connection.cc (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.cc#newco...
sql/connection.cc:1029: base::HistogramBase::kUmaTargetedHistogramFlag);
On 2015/05/21 22:54:48, rmcilroy wrote:
> Maybe make a helper function which creates a Medium times histogram with a
given
> name to avoid repeating the same parameters each time here.

Done.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h
File sql/connection.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcode40
sql/connection.h:40: }
On 2015/05/21 22:54:48, rmcilroy wrote:
> AFAIK friended classes don't need to be declared (they are forward declared on
> the spot in the friend declaration)

"no class named ..." error.  It may be because of the namespace, I don't get the
same complaint with a random class name.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcod...
sql/connection.h:595: void CommitTime(const base::TimeDelta& delta);
On 2015/05/21 22:54:48, rmcilroy wrote:
> I think it would be clearer with "Record" prefixed to each of these function
> names.

Done.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcod...
sql/connection.h:616: void ChangeHelper(const base::TimeDelta& delta, bool
read_only);
On 2015/05/21 22:54:48, rmcilroy wrote:
> nit - maybe RecordTimeAndChangesHelper?

Went with RecordTimeAndChanges(), helper seems redundant (they're all helpers!).

https://codereview.chromium.org/1145833002/diff/20001/sql/proxy.h
File sql/proxy.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/proxy.h#newcode15
sql/proxy.h:15: // issue.
On 2015/05/21 22:54:48, rmcilroy wrote:
> nit - mention this is just required for tests (assuming this is the case).

Done.

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc
File sql/statement.cc (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc#newcode61
sql/statement.cc:61: const base::TimeTicks before = base::TimeTicks::Now();
On 2015/05/21 22:54:48, rmcilroy wrote:
> You should probably only call base::TimerTicks::Now() if timer_flag is true
and
> you are going to use the result - it can be costly on some platforms.

Ugh, that maybe makes the logic icky because of the independent stack variables.
 I've shifted it to conditionally use base::TimeTicks::TimeTicks(), it's not
pretty, but I don't think there would be a performance downside.

How costly is costly?  Costly enough to make the overall approach questionable? 
I've been working under the assumption that measuring everything should be a
small fraction of the costs involved, but it would probably be fine to use
random sampling.

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h
File sql/statement.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h#newcode180
sql/statement.h:180: // the results.  The checked value from sqlite3_step() is
returned.
On 2015/05/21 22:54:48, rmcilroy wrote:
> "and histograms based on the results if |timer_flag| is true."

Done, maybe, but in terms of "How would I use this" I'm not sure it helps :-).

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.h#newcode181
sql/statement.h:181: int InnerStep(bool timer_flag);
On 2015/05/21 22:54:48, rmcilroy wrote:
> Maybe call StepInternal would be clearer?

Done.

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:40004: +<histogram
name="Sqlite.AutoCommitTime" units="milliseconds">
On 2015/05/21 22:54:48, rmcilroy wrote:
> Do you need to list the tagged versions too?

The tagged versions interact via the histogram_suffixes stanza at the bottom. 
Basically it abuses the field-trial infrastructure to generate the matrix of
things-being-measured versus database-histogram-tags.

I don't know what happens if we ever do a field trial on top of this :-).

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest...
sql/connection_unittest.cc:1143: ASSERT_TRUE(db().OpenInMemory());
I am having second thoughts about this test.  I wanted something to validate
that the timers were timing things, which is necessarily a bit heuristic, I
think (without some injection, I suppose).  Using a 10% safety net was fine on
all platforms except Android, which was slightly slower than that.  Removing the
filesystem from the equation looks a lot better, but ...

I think the options available would be to increase the sleep times to be enough
greater than the non-sleep overhead that it's more reliable, or to loosen the
upper bound, or perhaps even to only enable the test on a small number of
platforms which have high confidence of not being flaky.

I was aiming for high confidence that it would catch both "The time wasn't
measured at all" and "The time was measured twice", so in the single-sleep cases
100-175ish might work well, maybe the double-sleep case can just reduce to the
commit-time sleep, and assume that the other flows are correct.

[rmcilroy, 2015-05-22 08:48:23]

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h
File sql/connection.h (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcode40
sql/connection.h:40: }
On 2015/05/21 23:42:37, Scott Hess wrote:
> On 2015/05/21 22:54:48, rmcilroy wrote:
> > AFAIK friended classes don't need to be declared (they are forward declared
on
> > the spot in the friend declaration)
> 
> "no class named ..." error.  It may be because of the namespace, I don't get
the
> same complaint with a random class name.

Interesting, good to know.

https://codereview.chromium.org/1145833002/diff/20001/sql/connection.h#newcod...
sql/connection.h:616: void ChangeHelper(const base::TimeDelta& delta, bool
read_only);
On 2015/05/21 23:42:37, Scott Hess wrote:
> On 2015/05/21 22:54:48, rmcilroy wrote:
> > nit - maybe RecordTimeAndChangesHelper?
> 
> Went with RecordTimeAndChanges(), helper seems redundant (they're all
helpers!).

SGTM!

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc
File sql/statement.cc (right):

https://codereview.chromium.org/1145833002/diff/20001/sql/statement.cc#newcode61
sql/statement.cc:61: const base::TimeTicks before = base::TimeTicks::Now();
On 2015/05/21 23:42:37, Scott Hess wrote:
> On 2015/05/21 22:54:48, rmcilroy wrote:
> > You should probably only call base::TimerTicks::Now() if timer_flag is true
> and
> > you are going to use the result - it can be costly on some platforms.
> 
> Ugh, that maybe makes the logic icky because of the independent stack
variables.
>  I've shifted it to conditionally use base::TimeTicks::TimeTicks(), it's not
> pretty, but I don't think there would be a performance downside.
> 
> How costly is costly?  Costly enough to make the overall approach
questionable? 
> I've been working under the assumption that measuring everything should be a
> small fraction of the costs involved, but it would probably be fine to use
> random sampling.

Jared put together a list showing the cost of various operations on Android
(linked below) which show Now() as being 0.8 micro seconds (~4x a lock
operation) - I'm assuming this is fairly neglegable compared to the sql stuff
but just wanted to avoid doubling the overhead here.

https://docs.google.com/a/google.com/spreadsheets/d/1ulggKOZ7VQ8IytP1hKr-1wvB...

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/1145833002/diff/20001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:40004: +<histogram
name="Sqlite.AutoCommitTime" units="milliseconds">
On 2015/05/21 23:42:37, Scott Hess wrote:
> On 2015/05/21 22:54:48, rmcilroy wrote:
> > Do you need to list the tagged versions too?
> 
> The tagged versions interact via the histogram_suffixes stanza at the bottom. 
> Basically it abuses the field-trial infrastructure to generate the matrix of
> things-being-measured versus database-histogram-tags.
> 
> I don't know what happens if we ever do a field trial on top of this :-).

Interesting! Good to know for future reference.

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest...
sql/connection_unittest.cc:1143: ASSERT_TRUE(db().OpenInMemory());
On 2015/05/21 23:42:37, Scott Hess wrote:
> I am having second thoughts about this test.  I wanted something to validate
> that the timers were timing things, which is necessarily a bit heuristic, I
> think (without some injection, I suppose).  Using a 10% safety net was fine on
> all platforms except Android, which was slightly slower than that.  Removing
the
> filesystem from the equation looks a lot better, but ...
> 
> I think the options available would be to increase the sleep times to be
enough
> greater than the non-sleep overhead that it's more reliable, or to loosen the
> upper bound, or perhaps even to only enable the test on a small number of
> platforms which have high confidence of not being flaky.
> 
> I was aiming for high confidence that it would catch both "The time wasn't
> measured at all" and "The time was measured twice", so in the single-sleep
cases
> 100-175ish might work well, maybe the double-sleep case can just reduce to the
> commit-time sleep, and assume that the other flows are correct.

Yeah I agree, I was a bit worried about these tests being flaky too. One option
would be to make it possible for the sql layer to use an injected time source,
then the tests could set this time source to be a mock time source and your
tests can be deterministic. If you look at how we do this in
renderer_scheduler_impl_unittest.cc and
SchedulerHelper::SetTimeSourceForTesting().

[Scott Hess - ex-Googler, 2015-05-22 21:22:14]

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/40001/sql/connection_unittest...
sql/connection_unittest.cc:1143: ASSERT_TRUE(db().OpenInMemory());
On 2015/05/22 08:48:23, rmcilroy wrote:
> On 2015/05/21 23:42:37, Scott Hess wrote:
> > I am having second thoughts about this test.  I wanted something to validate
> > that the timers were timing things, which is necessarily a bit heuristic, I
> > think (without some injection, I suppose).  Using a 10% safety net was fine
on
> > all platforms except Android, which was slightly slower than that.  Removing
> the
> > filesystem from the equation looks a lot better, but ...
> > 
> > I think the options available would be to increase the sleep times to be
> enough
> > greater than the non-sleep overhead that it's more reliable, or to loosen
the
> > upper bound, or perhaps even to only enable the test on a small number of
> > platforms which have high confidence of not being flaky.
> > 
> > I was aiming for high confidence that it would catch both "The time wasn't
> > measured at all" and "The time was measured twice", so in the single-sleep
> cases
> > 100-175ish might work well, maybe the double-sleep case can just reduce to
the
> > commit-time sleep, and assume that the other flows are correct.
> 
> Yeah I agree, I was a bit worried about these tests being flaky too. One
option
> would be to make it possible for the sql layer to use an injected time source,
> then the tests could set this time source to be a mock time source and your
> tests can be deterministic. If you look at how we do this in
> renderer_scheduler_impl_unittest.cc and
> SchedulerHelper::SetTimeSourceForTesting().

OK, most recent patch mocks out the time source.  I like the better precision in
the tests.  It feels a little egregious implementation-wise, but I guess if this
prevents rollback due to flakiness, that's a positive!

[rmcilroy, 2015-05-26 10:06:25]

lgtm, thanks!

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest...
sql/connection_unittest.cc:1214: EXPECT_TRUE(db().Execute("SELECT
milliadjust(10)"));
nit - I would prefer the each of these tests as seperate functions (i.e.,
SQLConnectionTest::QueryTimes, SQLConnectionTest::UpdateTimes,
SQLConnectionTest::CommitTimes, etc.), however I'm not too fussed if you prefer
to keep it this way.

[Scott Hess - ex-Googler, 2015-05-29 20:17:08]

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest...
sql/connection_unittest.cc:1214: EXPECT_TRUE(db().Execute("SELECT
milliadjust(10)"));
On 2015/05/26 10:06:25, rmcilroy wrote:
> nit - I would prefer the each of these tests as seperate functions (i.e.,
> SQLConnectionTest::QueryTimes, SQLConnectionTest::UpdateTimes,
> SQLConnectionTest::CommitTimes, etc.), however I'm not too fussed if you
prefer
> to keep it this way.

This seems like a legit request, but wanted to verify - did you mean break out
each of the scoped cases as a separate test, or break out each of the
histograms?  This is sort of implementing a matrix of possibilities, so I guess
that comes out to row-major or column-major ordering.

[rmcilroy, 2015-05-29 20:30:17]

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest...
sql/connection_unittest.cc:1214: EXPECT_TRUE(db().Execute("SELECT
milliadjust(10)"));
On 2015/05/29 20:17:08, Scott Hess wrote:
> On 2015/05/26 10:06:25, rmcilroy wrote:
> > nit - I would prefer the each of these tests as seperate functions (i.e.,
> > SQLConnectionTest::QueryTimes, SQLConnectionTest::UpdateTimes,
> > SQLConnectionTest::CommitTimes, etc.), however I'm not too fussed if you
> prefer
> > to keep it this way.
> 
> This seems like a legit request, but wanted to verify - did you mean break out
> each of the scoped cases as a separate test, or break out each of the
> histograms?  This is sort of implementing a matrix of possibilities, so I
guess
> that comes out to row-major or column-major ordering.

I was meaning break out the scoped cases to separate tests.

[Scott Hess - ex-Googler, 2015-05-29 21:55:08]

shess@chromium.org changed reviewers:
+ michaeln@chromium.org

[Scott Hess - ex-Googler, 2015-05-29 21:55:09]

+michaneln for database_tracker.cc (minor reorder of sql::Connection calls)
+asvitkine for histograms.xml.

Thanks...

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest.cc
File sql/connection_unittest.cc (right):

https://codereview.chromium.org/1145833002/diff/80001/sql/connection_unittest...
sql/connection_unittest.cc:1214: EXPECT_TRUE(db().Execute("SELECT
milliadjust(10)"));
On 2015/05/29 20:30:17, rmcilroy wrote:
> On 2015/05/29 20:17:08, Scott Hess wrote:
> > On 2015/05/26 10:06:25, rmcilroy wrote:
> > > nit - I would prefer the each of these tests as seperate functions (i.e.,
> > > SQLConnectionTest::QueryTimes, SQLConnectionTest::UpdateTimes,
> > > SQLConnectionTest::CommitTimes, etc.), however I'm not too fussed if you
> > prefer
> > > to keep it this way.
> > 
> > This seems like a legit request, but wanted to verify - did you mean break
out
> > each of the scoped cases as a separate test, or break out each of the
> > histograms?  This is sort of implementing a matrix of possibilities, so I
> guess
> > that comes out to row-major or column-major ordering.
> 
> I was meaning break out the scoped cases to separate tests.

Yeah, the column-major breakdown turned out to be pretty brittle looking.  I
uploaded the row-major breakdown.

I think this change argues a bit for a modified test fixture which sets the
histogram tag.  I'd like to circle around with a different CL on that, though,
because the other change I want to land may impact how that should be broken
down.

[michaeln, 2015-06-01 22:25:26]

database_tracker.cc lgtm

[Scott Hess - ex-Googler, 2015-06-02 20:59:00]

shess@chromium.org changed reviewers:
+ askvitkine@chromium.org

[Scott Hess - ex-Googler, 2015-06-02 20:59:01]

Sorry, merely saying "+askvitkine for histograms.xml" doesn't actually add to
the reviewers list.  Trying again...

[Alexei Svitkine (slow), 2015-06-02 21:29:50]

asvitkine@chromium.org changed reviewers:
+ asvitkine@chromium.org
- askvitkine@chromium.org

[Alexei Svitkine (slow), 2015-06-02 21:29:51]

LGTM % nits

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h
File sql/connection.h (right):

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h#newco...
sql/connection.h:174: // Track various API calls and results.
Nit: Mention that these are used in UMA and so shouldn't be renumbered or
deleted.

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h#newco...
sql/connection.h:202: EVENT_MX
Nit: How about EVENT_MAX_VALUE or EVENT_HISTOGRAM_MAX?

https://codereview.chromium.org/1145833002/diff/100001/sql/proxy.h
File sql/proxy.h (right):

https://codereview.chromium.org/1145833002/diff/100001/sql/proxy.h#newcode1
sql/proxy.h:1: // Copyright (c) 2015 The Chromium Authors. All rights reserved.
Nit: No (c) for new files.

[Scott Hess - ex-Googler, 2015-06-02 22:13:44]

Thanks much.

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h
File sql/connection.h (right):

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h#newco...
sql/connection.h:174: // Track various API calls and results.
On 2015/06/02 21:29:51, Alexei Svitkine wrote:
> Nit: Mention that these are used in UMA and so shouldn't be renumbered or
> deleted.

Done.

https://codereview.chromium.org/1145833002/diff/100001/sql/connection.h#newco...
sql/connection.h:202: EVENT_MX
On 2015/06/02 21:29:51, Alexei Svitkine wrote:
> Nit: How about EVENT_MAX_VALUE or EVENT_HISTOGRAM_MAX?

Done.  Main reason was not to have to reflow a couple places it was used, but
now it's in a helper so *shrug*.

https://codereview.chromium.org/1145833002/diff/100001/sql/proxy.h
File sql/proxy.h (right):

https://codereview.chromium.org/1145833002/diff/100001/sql/proxy.h#newcode1
sql/proxy.h:1: // Copyright (c) 2015 The Chromium Authors. All rights reserved.
On 2015/06/02 21:29:51, Alexei Svitkine wrote:
> Nit: No (c) for new files.

Done.

[Scott Hess - ex-Googler, 2015-06-02 22:13:49]

The CQ bit was checked by shess@chromium.org

[Scott Hess - ex-Googler, 2015-06-02 22:13:49]

The patchset sent to the CQ was uploaded after l-g-t-m from
rmcilroy@chromium.org, michaeln@chromium.org, asvitkine@chromium.org
Link to the patchset: https://codereview.chromium.org/1145833002/#ps120001
(title: "asvitkine nits.")

[commit-bot: I haz the power, 2015-06-02 22:14:49]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1145833002/120001

[commit-bot: I haz the power, 2015-06-03 00:19:42]

Committed patchset #7 (id:120001)

[commit-bot: I haz the power, 2015-06-03 00:20:31]

Patchset 7 (id:??) landed as
https://crrev.com/58b8df8572e25ff91b3073213651aed4ebd675b5
Cr-Commit-Position: refs/heads/master@{#332503}