|
|
Created:
4 years, 2 months ago by vakh (use Gerrit instead) Modified:
4 years, 1 month ago CC:
chromium-reviews, vakh+watch_chromium.org Target Ref:
refs/pending/heads/master Project:
chromium Visibility:
Public. |
DescriptionPVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check
SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory.
SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL.
SB2.Network: The time it takes to get the full hash response from the server and parse it.
This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results:
+ SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time
+ SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time
+ SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time
Adding these metrics would allow us to do a more reasonable comparison.
BUG=543161
Committed: https://crrev.com/9ba50173ad377dcb9dadeb6dc1389929e23f65aa
Cr-Commit-Position: refs/heads/master@{#426985}
Patch Set 1 #Patch Set 2 : git rebase #
Total comments: 10
Patch Set 3 : nparker@'s review #Patch Set 4 : Add new histograms to histograms.xml #
Total comments: 9
Patch Set 5 : nparker@'s review #
Total comments: 1
Messages
Total messages: 40 (26 generated)
The CQ bit was checked by vakh@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
git rebase
The CQ bit was checked by vakh@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times and got the following results that show: + SB2.DatabaseOpen is consistently faster for PVer4 by + SB2.FilterCheck is consistently faster for PVer4 by + SB2.Network is consistently faster for PVer4 by (18:37:14) $ grep SB2 /tmp/profile/1477013743.run.out [45553:45630:1020/183551:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.039472s [45553:45662:1020/183551:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.083619s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009531s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000769s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.19115s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.23848s (18:37:23) $ grep SB2 /tmp/profile/1477013851.run.out [47505:47541:1020/183734:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.04293s [47505:47573:1020/183734:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.088538s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009735s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000753s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.240445s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.241837s (18:37:51) $ grep SB2 /tmp/profile/1477013904.run.out [48177:48223:1020/183827:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035169s [48177:48255:1020/183827:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.08875s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.011505s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000532s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.191771s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.192896s (18:38:49) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [49735:49758:1020/184025:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.0349s [49735:49790:1020/184025:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.108486s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.008185s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000594s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.199895s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.200927s (18:42:36) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [51559:51595:1020/184301:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035266s [51559:51627:1020/184301:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.090279s [51559:51601:1020/184301:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.007963s [51559:51601:1020/184301:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000484s [51559:51601:1020/184302:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.233418s [51559:51601:1020/184302:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.234775s BUG=543161 ==========
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times and got the following results that show: + SB2.DatabaseOpen is consistently faster for PVer4 by + SB2.FilterCheck is consistently faster for PVer4 by + SB2.Network is consistently faster for PVer4 by (18:37:14) $ grep SB2 /tmp/profile/1477013743.run.out [45553:45630:1020/183551:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.039472s [45553:45662:1020/183551:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.083619s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009531s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000769s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.19115s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.23848s (18:37:23) $ grep SB2 /tmp/profile/1477013851.run.out [47505:47541:1020/183734:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.04293s [47505:47573:1020/183734:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.088538s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009735s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000753s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.240445s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.241837s (18:37:51) $ grep SB2 /tmp/profile/1477013904.run.out [48177:48223:1020/183827:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035169s [48177:48255:1020/183827:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.08875s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.011505s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000532s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.191771s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.192896s (18:38:49) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [49735:49758:1020/184025:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.0349s [49735:49790:1020/184025:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.108486s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.008185s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000594s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.199895s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.200927s (18:42:36) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [51559:51595:1020/184301:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035266s [51559:51627:1020/184301:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.090279s [51559:51601:1020/184301:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.007963s [51559:51601:1020/184301:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000484s [51559:51601:1020/184302:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.233418s [51559:51601:1020/184302:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.234775s BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times and got the following results that show: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s) + SB2.FilterCheck is consistently faster for PVer4 by 93% (0.0093838s vs 0.0006264s) + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s) (18:37:14) $ grep SB2 /tmp/profile/1477013743.run.out [45553:45630:1020/183551:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.039472s [45553:45662:1020/183551:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.083619s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009531s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000769s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.19115s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.23848s (18:37:23) $ grep SB2 /tmp/profile/1477013851.run.out [47505:47541:1020/183734:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.04293s [47505:47573:1020/183734:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.088538s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009735s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000753s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.240445s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.241837s (18:37:51) $ grep SB2 /tmp/profile/1477013904.run.out [48177:48223:1020/183827:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035169s [48177:48255:1020/183827:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.08875s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.011505s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000532s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.191771s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.192896s (18:38:49) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [49735:49758:1020/184025:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.0349s [49735:49790:1020/184025:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.108486s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.008185s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000594s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.199895s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.200927s (18:42:36) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [51559:51595:1020/184301:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035266s [51559:51627:1020/184301:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.090279s [51559:51601:1020/184301:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.007963s [51559:51601:1020/184301:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000484s [51559:51601:1020/184302:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.233418s [51559:51601:1020/184302:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.234775s BUG=543161 ==========
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times and got the following results that show: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s) + SB2.FilterCheck is consistently faster for PVer4 by 93% (0.0093838s vs 0.0006264s) + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s) (18:37:14) $ grep SB2 /tmp/profile/1477013743.run.out [45553:45630:1020/183551:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.039472s [45553:45662:1020/183551:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.083619s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009531s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000769s [45553:45636:1020/183551:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.19115s [45553:45636:1020/183551:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.23848s (18:37:23) $ grep SB2 /tmp/profile/1477013851.run.out [47505:47541:1020/183734:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.04293s [47505:47573:1020/183734:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.088538s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.009735s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000753s [47505:47547:1020/183734:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.240445s [47505:47547:1020/183734:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.241837s (18:37:51) $ grep SB2 /tmp/profile/1477013904.run.out [48177:48223:1020/183827:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035169s [48177:48255:1020/183827:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.08875s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.011505s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000532s [48177:48229:1020/183827:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.191771s [48177:48229:1020/183827:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.192896s (18:38:49) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [49735:49758:1020/184025:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.0349s [49735:49790:1020/184025:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.108486s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.008185s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000594s [49735:49764:1020/184026:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.199895s [49735:49764:1020/184026:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.200927s (18:42:36) $ grep SB2 (ls /tmp/profile/*.run.out | tail -n 1) [51559:51595:1020/184301:VERBOSE1:v4_database.cc(82)] SB2.DatabaseOpen: 0.035266s [51559:51627:1020/184301:VERBOSE1:local_database_manager.cc(827)] SB2.DatabaseOpen: 0.090279s [51559:51601:1020/184301:VERBOSE1:local_database_manager.cc(533)] SB2.FilterCheck: 0.007963s [51559:51601:1020/184301:VERBOSE1:v4_local_database_manager.cc(366)] SB2.FilterCheck: 0.000484s [51559:51601:1020/184302:VERBOSE1:local_database_manager.cc(599)] SB2.Network: 0.233418s [51559:51601:1020/184302:VERBOSE1:v4_local_database_manager.cc(421)] SB2.Network: 0.234775s BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s) + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s) + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ==========
vakh@chromium.org changed reviewers: + nparker@chromium.org, shess@chromium.org
https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_database.cc (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_database.cc:81: UMA_HISTOGRAM_TIMES("SB2.DatabaseOpen", TimeTicks::Now() - before); note: This time includes the time to post onto this runner, but not back onto the IO thread. That's probably fine (the second post might take few ms), but let's make sure it's apples-to-apples with Pver3. In the Hybrid experiment group, Chrome will log to this metric twice, once for v3 and once for v4. That will make this metric useless in that group since the two distributions will be mashed together. Sooo.. Maybe it makes sense to log this to your new suggested metric for now. It'll mean it'll be a bit harder to compare the two come v4only mode, but it's at least possible. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_database.h (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_database.h:168: const base::TimeTicks before); How about "create_start_time?" "before" is nonobvious. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:365: UMA_HISTOGRAM_TIMES("SB2.FilterCheck", TimeTicks::Now() - before); This is almost always < 1 ms. I think we should log it like this for comparison to pver3, but maybe also log it to your suggested new metric in microseconds. The latter would be useful to detect/measure any performance changes in this code. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:417: // SafeBrowsing.V4GetFullHashOverNetwork.Time once PVer3 code is removed. an aside: There is a SafeBrowsing.GetV4HashResult. Maybe that should be V4GetFullHash.Result? Feel free to lay these out in the spreadsheet. It's helpful to see them all in one place to make it clear what the patterns are. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.h (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.h:112: // When the check was sent to the SafeBrowsing service. Used to record the I'm not clear on this description. Is it the full-hash-check sent to the "safebrowsing.google.com" service, or is the Check*() check? Maybe full_hash_check_start? or network_start_time?
Thanks for taking a look. PTAL. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_database.cc (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_database.cc:81: UMA_HISTOGRAM_TIMES("SB2.DatabaseOpen", TimeTicks::Now() - before); On 2016/10/21 20:21:18, Nathan Parker wrote: > note: This time includes the time to post onto this runner, but not back onto > the IO thread. That's probably fine (the second post might take few ms), but > let's make sure it's apples-to-apples with Pver3. > PVer3 has the same. > In the Hybrid experiment group, Chrome will log to this metric twice, once for > v3 and once for v4. That will make this metric useless in that group since the > two distributions will be mashed together. Sooo.. Maybe it makes sense to log > this to your new suggested metric for now. It'll mean it'll be a bit harder to > compare the two come v4only mode, but it's at least possible. > Done. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_database.h (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_database.h:168: const base::TimeTicks before); On 2016/10/21 20:21:19, Nathan Parker wrote: > How about "create_start_time?" "before" is nonobvious. Done. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:365: UMA_HISTOGRAM_TIMES("SB2.FilterCheck", TimeTicks::Now() - before); On 2016/10/21 20:21:19, Nathan Parker wrote: > This is almost always < 1 ms. I think we should log it like this for comparison > to pver3, but maybe also log it to your suggested new metric in microseconds. > The latter would be useful to detect/measure any performance changes in this > code. Done. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:417: // SafeBrowsing.V4GetFullHashOverNetwork.Time once PVer3 code is removed. On 2016/10/21 20:21:19, Nathan Parker wrote: > an aside: There is a SafeBrowsing.GetV4HashResult. Maybe that should be > V4GetFullHash.Result? > Yes, I need to correct the metrics in that file. On my radar. > Feel free to lay these out in the spreadsheet. It's helpful to see them all in > one place to make it clear what the patterns are. Ack. https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.h (right): https://codereview.chromium.org/2441923003/diff/20001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.h:112: // When the check was sent to the SafeBrowsing service. Used to record the On 2016/10/21 20:21:19, Nathan Parker wrote: > I'm not clear on this description. Is it the full-hash-check sent to the > "safebrowsing.google.com" service, or is the Check*() check? > > Maybe full_hash_check_start? or network_start_time? Done.
nparker@'s review
The CQ bit was checked by vakh@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Add new histograms to histograms.xml
The CQ bit was checked by vakh@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s) + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s) + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ==========
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ==========
vakh@chromium.org changed reviewers: + holte@chromium.org
holte@ -- can you please review the changes in tools/metrics/histograms/histograms.xml Thanks!
histograms lgtm
lgtm https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... File components/safe_browsing_db/v4_database.h (right): https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_database.h:168: const base::TimeTicks before); create_start_time, like the .cc https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:368: base::TimeDelta::FromMicroseconds(100), Does this generate a log or linear scale of buckets? Linear would be bad since it'd be (20.1/50) = 402ms buckets, which doesn't help much. I _think_ it'll do log-spaced buckets, which should be fine. I'd put the max at 1 second, since anything above that for local memory access is really broken and therefore uninteresting. And then the minimum could move lower, say to 20us. If you want to tune it more carefully, you could try it on a release build, load up cnn.com, and verify the histogram has good resolution around the common values. We should note that this doesn't distinguish which DBs it's searching through. The vast majority of the entries in this histogram will be from searching the three BrowseURL DBs.(I don't think it's really worth logging them separately.) https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:450: check->full_hash_check_start = TimeTicks::Now(); Ah, so this will won't distinguish network calls vs cache hits, ya? If not, you could put this in the protocol_manager so it can log just network requests. https://codereview.chromium.org/2441923003/diff/60001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2441923003/diff/60001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:51817: + The time that it took to check a URL against our in-memory database. Maybe note that this is the sum of all in-memory checks, but dominated by CheckBrowseUrl.
nparker@'s review
The CQ bit was checked by vakh@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Thanks for the review nparker@ and holte@ shess@ -- I will submit this CL soon but please do review the changes. I'll upload the changes from your review as a separate CL. https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... File components/safe_browsing_db/v4_database.h (right): https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_database.h:168: const base::TimeTicks before); On 2016/10/22 00:24:55, Nathan Parker wrote: > create_start_time, like the .cc Done. https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:368: base::TimeDelta::FromMicroseconds(100), On 2016/10/22 00:24:55, Nathan Parker wrote: > Does this generate a log or linear scale of buckets? Linear would be bad since > it'd be (20.1/50) = 402ms buckets, which doesn't help much. I _think_ it'll do > log-spaced buckets, which should be fine. > > I'd put the max at 1 second, since anything above that for local memory access > is really broken and therefore uninteresting. And then the minimum could move > lower, say to 20us. If you want to tune it more carefully, you could try it on a > release build, load up http://cnn.com, and verify the histogram has good resolution > around the common values. > > We should note that this doesn't distinguish which DBs it's searching through. > The vast majority of the entries in this histogram will be from searching the > three BrowseURL DBs.(I don't think it's really worth logging them separately.) Done. The comments for UMA_HISTOGRAM_CUSTOM_TIMES suggest log scale. UMA_HISTOGRAM_TIMES uses UMA_HISTOGRAM_CUSTOM_TIMES so it should be consistent with the other histograms that we have. https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:450: check->full_hash_check_start = TimeTicks::Now(); On 2016/10/22 00:24:55, Nathan Parker wrote: > Ah, so this will won't distinguish network calls vs cache hits, ya? If not, you > could put this in the protocol_manager so it can log just network requests. Done. https://codereview.chromium.org/2441923003/diff/60001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2441923003/diff/60001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:51817: + The time that it took to check a URL against our in-memory database. On 2016/10/22 00:24:55, Nathan Parker wrote: > Maybe note that this is the sum of all in-memory checks, but dominated by > CheckBrowseUrl. Done.
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ==========
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: This issue passed the CQ dry run.
The CQ bit was checked by vakh@chromium.org
The patchset sent to the CQ was uploaded after l-g-t-m from nparker@chromium.org, holte@chromium.org Link to the patchset: https://codereview.chromium.org/2441923003/#ps80001 (title: "nparker@'s review")
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Message was sent while issue was closed.
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ==========
Message was sent while issue was closed.
Committed patchset #5 (id:80001)
Message was sent while issue was closed.
Description was changed from ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 ========== to ========== PVer4: Add UMA metrics for time taken to: load DB, do prefix check, and network time to do full hash check SB2.DatabaseOpen: The time it takes to read, parse, and load the database from disk into memory. SB2.FilterCheck: The time it takes to check the prefix hashes for a match. I tested a known phishing URL. SB2.Network: The time it takes to get the full hash response from the server and parse it. This is anecdotal, but I ran the two DB managers in parallel mode 5 times (5 different launches of Chrome) and got the following results: + SB2.DatabaseOpen is consistently faster for PVer4 by 59% (0.0919344s vs 0.0375474s). The PVer4 version is called: SafeBrowsing.V4DatabaseOpen.Time + SB2.FilterCheck is consistently faster for PVer4 by 30% (0.0093838s vs 0.00659247s). The PVer4 version is called: SafeBrowsing.V4GetPrefixMatches.Time + SB2.Network is consistently *slower* for PVer4 by 4.94% (0.2113358s vs 0.221783s). -- This slowness needs to be investigated but is somewhat acceptable since this is only used for 1/1000 hash checks. The PVer4 version is called: SafeBrowsing.V4GetHashNetwork.Time Adding these metrics would allow us to do a more reasonable comparison. BUG=543161 Committed: https://crrev.com/9ba50173ad377dcb9dadeb6dc1389929e23f65aa Cr-Commit-Position: refs/heads/master@{#426985} ==========
Message was sent while issue was closed.
Patchset 5 (id:??) landed as https://crrev.com/9ba50173ad377dcb9dadeb6dc1389929e23f65aa Cr-Commit-Position: refs/heads/master@{#426985}
Message was sent while issue was closed.
Treat these as peanut-gallery comments, I don't think they necessarily require action. https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/60001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:368: base::TimeDelta::FromMicroseconds(100), On 2016/10/22 01:34:34, vakh (Varun Khaneja) wrote: > On 2016/10/22 00:24:55, Nathan Parker wrote: > > Does this generate a log or linear scale of buckets? Linear would be bad > since > > it'd be (20.1/50) = 402ms buckets, which doesn't help much. I _think_ it'll do > > log-spaced buckets, which should be fine. > > > > I'd put the max at 1 second, since anything above that for local memory access > > is really broken and therefore uninteresting. And then the minimum could move > > lower, say to 20us. If you want to tune it more carefully, you could try it on > a > > release build, load up http://cnn.com, and verify the histogram has good > resolution > > around the common values. > > > > We should note that this doesn't distinguish which DBs it's searching through. > > > The vast majority of the entries in this histogram will be from searching the > > three BrowseURL DBs.(I don't think it's really worth logging them separately.) > > Done. The comments for UMA_HISTOGRAM_CUSTOM_TIMES suggest log scale. > UMA_HISTOGRAM_TIMES uses UMA_HISTOGRAM_CUSTOM_TIMES so it should be consistent > with the other histograms that we have. Log scale unless you're doing something special. Given log scale, IMHO be conservative about how tight you make things. The difference between 1s and 20s is only going to add like 5 buckets. So if 1s is literally "I don't even", then fine. I usually aim to have very few hits in the overflow bucket, simply because the improved precision is often not all that valuable, but having to respin the entire histogram entry is annoying :-). https://codereview.chromium.org/2441923003/diff/80001/components/safe_browsin... File components/safe_browsing_db/v4_local_database_manager.cc (right): https://codereview.chromium.org/2441923003/diff/80001/components/safe_browsin... components/safe_browsing_db/v4_local_database_manager.cc:360: NOTREACHED() << "Unexpected client_callback_type encountered"; Is this case guaranteed to be nominal to nonexistent? Otherwise you might end up with a lot of not-interesting min-bucket values. |