Add UMA metrics for the time it takes to read store from disk and apply update

Add UMA metrics for the time it takes to read store from disk and apply update

BUG=651911, 543161
Committed: https://crrev.com/8ccfe9a0fb1404e2d09d39010744a7f58458848d
Cr-Commit-Position: refs/heads/master@{#422968}

[vakh (use Gerrit instead), 2016-09-30 19:32:50]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-09-30 19:33:16]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[vakh (use Gerrit instead), 2016-09-30 19:55:25]

vakh@chromium.org changed reviewers:
+ nparker@chromium.org

[vakh (use Gerrit instead), 2016-09-30 19:57:50]

vakh@chromium.org changed reviewers:
+ rkaplow@chromium.org

[vakh (use Gerrit instead), 2016-09-30 19:57:51]

rkaplow@: Please review the changes in histograms.xml

[commit-bot: I haz the power, 2016-09-30 20:33:16]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-09-30 20:33:17]

Dry run: This issue passed the CQ dry run.

[Nathan Parker, 2016-09-30 22:32:05]

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
File components/safe_browsing_db/v4_store.cc (right):

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:26: void
RecordAddUnlumpedHashesTime(base::TimeDelta time) {
style nit: Personally I think it's easier to follow if the UMA metric is placed
right in the code. The place where I'd use a function is if it were used more
than once, and you want to ensure consistency and type checking.

[talked offline about adding store_name to these]
So if you're adding store name, then you might want these functions, or even add
them to the class so they can access the store_id/name directly.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:144: base::TimeTicks before =
base::TimeTicks::Now();
I'd add a 
using base::TimeTicks
to simplify all of this.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:148:
RecordProcessPartialUpdateTime(after - before);
nit: You can skip the |afer| and just do TimeTicks::Now() - before. Less
verbiage.  Here and elsewhere.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:351: base::TimeTicks before =
base::TimeTicks::Now();
What is this recording?  The copying of the string?  Does UMA record time with
sufficient precision to make this an actionable metric?

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50798: +  <summary>
Can you annotate each of these for cases where one includes another one? It's
not obvious from the descriptions

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50801: +    case of reading the store
from disk on start-up.
"...or it may have just been read from disk."

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50810: +    it takes to convert the
update into a hash map that's looked up on resource
what is looked up on resource reputation requests?  I don't understand that
part. Same below.

[vakh (use Gerrit instead), 2016-10-03 21:17:33]

Also log per store UMA metrics for time. Detailed explanation of histograms.
Other minor changes.

[vakh (use Gerrit instead), 2016-10-03 21:17:35]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-03 21:18:18]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[vakh (use Gerrit instead), 2016-10-03 21:30:11]

Refactored histogram comments

[vakh (use Gerrit instead), 2016-10-03 21:30:16]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[vakh (use Gerrit instead), 2016-10-03 21:30:37]

Thanks, PTAL.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
File components/safe_browsing_db/v4_store.cc (right):

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:26: void
RecordAddUnlumpedHashesTime(base::TimeDelta time) {
On 2016/09/30 22:32:05, Nathan Parker wrote:
> style nit: Personally I think it's easier to follow if the UMA metric is
placed
> right in the code. The place where I'd use a function is if it were used more
> than once, and you want to ensure consistency and type checking.
> 
> [talked offline about adding store_name to these]
> So if you're adding store name, then you might want these functions, or even
add
> them to the class so they can access the store_id/name directly.

Done. Added the store specific histograms for Time only for now since this CL is
adding time related metrics.
I'll add the per-store metrics for result enums as a separate CL.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:144: base::TimeTicks before =
base::TimeTicks::Now();
On 2016/09/30 22:32:05, Nathan Parker wrote:
> I'd add a 
> using base::TimeTicks
> to simplify all of this.

Done.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:148:
RecordProcessPartialUpdateTime(after - before);
On 2016/09/30 22:32:05, Nathan Parker wrote:
> nit: You can skip the |afer| and just do TimeTicks::Now() - before. Less
> verbiage.  Here and elsewhere.

Done.

https://codereview.chromium.org/2383063003/diff/1/components/safe_browsing_db...
components/safe_browsing_db/v4_store.cc:351: base::TimeTicks before =
base::TimeTicks::Now();
On 2016/09/30 22:32:05, Nathan Parker wrote:
> What is this recording?  The copying of the string?  Does UMA record time with
> sufficient precision to make this an actionable metric?

My goal is to remove the TODO.
If UMA shows that this operation doesn't take any considerable amount of time,
that would be an argument for removing the TODO.

The other concern would be to reuse memory but since this operation happens
~once per list every ~15-30 mins, it is probably not worth optimizing.

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50798: +  <summary>
On 2016/09/30 22:32:05, Nathan Parker wrote:
> Can you annotate each of these for cases where one includes another one? It's
> not obvious from the descriptions

Done.

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50801: +    case of reading the store
from disk on start-up.
On 2016/09/30 22:32:05, Nathan Parker wrote:
> "...or it may have just been read from disk."

Done.

https://codereview.chromium.org/2383063003/diff/1/tools/metrics/histograms/hi...
tools/metrics/histograms/histograms.xml:50810: +    it takes to convert the
update into a hash map that's looked up on resource
On 2016/09/30 22:32:05, Nathan Parker wrote:
> what is looked up on resource reputation requests?  I don't understand that
> part. Same below.

Done. PLMK if the new description is also not clear.

[commit-bot: I haz the power, 2016-10-03 21:30:39]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-03 22:03:24]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-03 22:03:25]

Dry run: Try jobs failed on following builders:
  win_chromium_compile_dbg_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_comp...)

[vakh (use Gerrit instead), 2016-10-03 22:10:01]

Use StringType otherwise Windows builds fail

[vakh (use Gerrit instead), 2016-10-03 22:10:04]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-03 22:10:41]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-03 22:46:50]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-03 22:46:51]

Dry run: Try jobs failed on following builders:
  win_chromium_compile_dbg_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_comp...)

[vakh (use Gerrit instead), 2016-10-03 22:49:48]

Use StringType with FILE_PATH_LITERAL

[vakh (use Gerrit instead), 2016-10-03 22:49:51]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-03 22:50:22]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[vakh (use Gerrit instead), 2016-10-03 22:50:48]

Use StringType with FILE_PATH_LITERAL

[vakh (use Gerrit instead), 2016-10-03 22:50:50]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[vakh (use Gerrit instead), 2016-10-03 22:51:04]

Patchset #5 (id:80001) has been deleted

[commit-bot: I haz the power, 2016-10-03 22:51:36]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-03 23:34:18]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-03 23:34:19]

Dry run: Try jobs failed on following builders:
  win_chromium_rel_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_rel_...)

[vakh (use Gerrit instead), 2016-10-04 16:28:04]

Use base::StringPrintf to generate the partial histogram name. Thanks Windows!

[vakh (use Gerrit instead), 2016-10-04 16:28:10]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-10-04 16:28:29]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[vakh (use Gerrit instead), 2016-10-04 16:28:30]

Patchset #4 (id:60001) has been deleted

[vakh (use Gerrit instead), 2016-10-04 16:28:47]

Patchset #4 (id:100001) has been deleted

[rkaplow, 2016-10-04 17:09:55]

lgtm

[commit-bot: I haz the power, 2016-10-04 17:49:36]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-10-04 17:49:38]

Dry run: Try jobs failed on following builders:
  linux_android_rel_ng on master.tryserver.chromium.android (JOB_FAILED,
https://build.chromium.org/p/tryserver.chromium.android/builders/linux_androi...)

[Nathan Parker, 2016-10-04 20:30:44]

lgtm

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
File components/safe_browsing_db/v4_store.cc (right):

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
components/safe_browsing_db/v4_store.cc:31: ".%" PRIsFP,
file_path.BaseName().RemoveExtension().value().c_str());
[no action required] Is this just a way to convert to UTF8?  I think we're
assuming the filename is ASCII anyway. You might be able to use MaybeAsASCII().

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
components/safe_browsing_db/v4_store.cc:44: base::TimeDelta::FromHours(1), 50,
What bucket values does this produce? I'm guessing we don't care about precision
above, say 30 seconds.  Might as well use that precision down lower in the few
ms range.

[vakh (use Gerrit instead), 2016-10-04 21:05:15]

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
File components/safe_browsing_db/v4_store.cc (right):

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
components/safe_browsing_db/v4_store.cc:31: ".%" PRIsFP,
file_path.BaseName().RemoveExtension().value().c_str());
On 2016/10/04 20:30:43, Nathan Parker wrote:
> [no action required] Is this just a way to convert to UTF8?  I think we're
> assuming the filename is ASCII anyway. You might be able to use
MaybeAsASCII().

The file is always ASCII since we chose the name for it.
The current implementation is consistent with the DebugString so it might be
good to keep it as is.

https://codereview.chromium.org/2383063003/diff/120001/components/safe_browsi...
components/safe_browsing_db/v4_store.cc:44: base::TimeDelta::FromHours(1), 50,
On 2016/10/04 20:30:44, Nathan Parker wrote:
> What bucket values does this produce? I'm guessing we don't care about
precision
> above, say 30 seconds.  Might as well use that precision down lower in the few
> ms range.

The bucket count is 50. It's the same as UMA_HISTOGRAM_LONG_TIMES.
I could change the bucket count to 100 and reduce the maximum to 1 minute (just
to be safe). WDYT?

[vakh (use Gerrit instead), 2016-10-04 21:09:33]

Reduce the max value and increase the number of buckets in histogram.

[vakh (use Gerrit instead), 2016-10-04 21:09:36]

The CQ bit was checked by vakh@chromium.org to run a CQ dry run

[vakh (use Gerrit instead), 2016-10-04 21:09:37]

The CQ bit was checked by vakh@chromium.org

[vakh (use Gerrit instead), 2016-10-04 21:09:38]

The patchset sent to the CQ was uploaded after l-g-t-m from
nparker@chromium.org, rkaplow@chromium.org
Link to the patchset: https://codereview.chromium.org/2383063003/#ps140001
(title: "Reduce the max value and increase the number of buckets in histogram.")

[commit-bot: I haz the power, 2016-10-04 21:10:37]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-10-04 22:25:45]

Committed patchset #5 (id:140001)

[commit-bot: I haz the power, 2016-10-04 22:28:00]

Description was changed from

==========
Add UMA metrics for the time it takes to read store from disk and apply update

BUG=651911, 543161
==========

to

==========
Add UMA metrics for the time it takes to read store from disk and apply update

BUG=651911, 543161

Committed: https://crrev.com/8ccfe9a0fb1404e2d09d39010744a7f58458848d
Cr-Commit-Position: refs/heads/master@{#422968}
==========

[commit-bot: I haz the power, 2016-10-04 22:28:01]

Patchset 5 (id:??) landed as
https://crrev.com/8ccfe9a0fb1404e2d09d39010744a7f58458848d
Cr-Commit-Position: refs/heads/master@{#422968}