Report Precache.TimeSinceLastPrecache

components/precache/core/precache_database.cc

Index: components/precache/core/precache_database.cc
diff --git a/components/precache/core/precache_database.cc b/components/precache/core/precache_database.cc
index e9d53ecad16d8bc30ebd4415013430d1bd131dda..40c2c730b008c992eecbba393abadb85e3d8b1ae 100644
--- a/components/precache/core/precache_database.cc
+++ b/components/precache/core/precache_database.cc
@@ -23,6 +23,9 @@ namespace {
 // it is considered "old" and is removed from the table.
 const int kPrecacheHistoryExpiryPeriodDays = 60;
 
+const int kSecondsInMinute = 60;
+const int kSecondsInDay = kSecondsInMinute * 60 * 24;
+
 }  // namespace
 
 namespace precache {
@@ -90,6 +93,30 @@ void PrecacheDatabase::ClearHistory() {
   Flush();
 }
 
+void PrecacheDatabase::SetLastPrecacheTimestamp(const base::Time& time) {
+  last_precache_timestamp_ = time;
+
+  if (!IsDatabaseAccessible()) {
+    // Do nothing if unable to access the database.
+    return;
+  }
+
+  buffered_writes_.push_back(
+      base::Bind(&PrecacheSessionTable::SetLastPrecacheTimestamp,
+                 base::Unretained(&precache_session_table_), time));
+  MaybePostFlush();
+}
+
+base::Time PrecacheDatabase::GetLastPrecacheTimestamp() {
+  if (!last_precache_timestamp_.is_null() || !IsDatabaseAccessible()) {

[twifkak, 2016/07/08 23:47:53]

Nit: Can get rid of the redundant return statement by negating the condition
clause:

base::Time PrecacheDatabase::GetLastPrecacheTimestamp() {
  if (last_precache_timestamp_.is_null() && IsDatableAccessible())
    last_precache_timestamp_ =
precache_session_table_.GetLastPrecacheTimestamp();
  return last_precache_timestamp_;
}

[jamartin, 2016/07/12 14:18:44]

Good point.

+    // Use the cached value, possibly not initialized (and hence is_null()).
+    return last_precache_timestamp_;
+  }
+
+  last_precache_timestamp_ = precache_session_table_.GetLastPrecacheTimestamp();
+  return last_precache_timestamp_;
+}
+
 void PrecacheDatabase::RecordURLPrefetch(const GURL& url,
                                          const base::TimeDelta& latency,
                                          const base::Time& fetch_time,
@@ -157,6 +184,8 @@ void PrecacheDatabase::RecordURLNonPrefetch(const GURL& url,
     return;
   }
 
+  RecordTimeSinceLastPrecache(fetch_time);
+
   if (buffered_urls_.find(url.spec()) != buffered_urls_.end()) {
     // If the URL for this fetch is in the write buffer, then flush the write
     // buffer.
@@ -201,6 +230,26 @@ void PrecacheDatabase::RecordURLNonPrefetch(const GURL& url,
   MaybePostFlush();
 }
 
+void PrecacheDatabase::RecordTimeSinceLastPrecache(
+    const base::Time& fetch_time) {
+  if (last_precache_timestamp_.is_null()) {

[twifkak, 2016/07/08 23:47:53]

Why don't you just call [this->]GetLastPrecacheTimestamp here?

[jamartin, 2016/07/12 14:18:44]

Good point.

This grew organically. This GetLastPrecacheTimestamp was originally meant as
code just for testing, then Raj suggested an improvement, and now you ended up
suggesting using it in the main path.

+    last_precache_timestamp_ =
+        precache_session_table_.GetLastPrecacheTimestamp();
+  }
+  // It could still be null if the DB was not accessible.
+  if (!last_precache_timestamp_.is_null()) {
+    // This is the timespan (in seconds) between the last call to
+    // PrecacheManager::StartPrecaching and the fetch time of a non-precache
+    // URL. Please note that the session started by that call to
+    // PrecacheManager::StartPrecaching may not have precached this particular
+    // URL or even any URL for that matter.
+    UMA_HISTOGRAM_CUSTOM_COUNTS(
+        "Precache.TimeSinceLastPrecache",
+        (fetch_time - last_precache_timestamp_).InSeconds(),
+        kSecondsInMinute,  kSecondsInDay, 100);

[rkaplow, 2016/07/08 14:37:59]

not really obvious to me you have a min of 60 - why not 0 here? (for
kSecondsInMinute)

[rkaplow, 2016/07/08 14:37:59]

picking the max as a day seems fine though (responding to your comment about
unsure what to pick). THat is - if that is the full range you are interested in.

[jamartin, 2016/07/08 14:52:49]

Thanks. Ideally I'd like more than a day, probably a week, but then the buckets
start to get too big (if split equally, now they would be about 15 min wide as
they currently are).

If twifkak@ agrees, we'll start with these buckets and we'll revisit the range
if we see that most of our entries are in the max.

[jamartin, 2016/07/08 14:52:49]

0 is not a valid min as per Histogram::FactoryGet. Besides, this event is
supposed to happen in the middle of the night when there is no interaction with
the user. If the user navigated less than a minute after this took place, I
don't need to know the time delta with any more resolution than that. 

[twifkak, 2016/07/08 23:47:53]

IIRC, the advice I was given a while back was to make sure the 95%ile was not in
the overflow bucket, give or take. (Or was it 99%ile? I don't remember.)

Looking at
https://uma.googleplex.com/p/chrome/histograms/?endDate=07-07-2016&dayCount=1...,
we see that the 95%ile for precache interval is around 50 hours. This is
probably an underestimate, as that UMA only reports if precache runs a second
time.

If we assume that the time of a NonPrefetch request is independent from the time
of a Prefetch request, then 50/2=25 hours seems like a reasonable 95%ile for
time-since-precache then. But given this is a bit of guesswork, I'd be inclined
to go with ~36 hours. After all, if you overestimate your max, then your bucket
sizes are a bit too large. If you underestimate your max, then your last bucket
size is _way_ too large.

A couple of side notes:

1. By default buckets are not split linearly, but exponentially (i.e. UMA
assumes that your metric has lognormal distribution).

2. Buckets are not supposed to be changed on UMAs. One must deprecate the old
and rename the metric to BlahBlah2.

WDYT?

[jamartin, 2016/07/12 14:18:44]

Done (max = 36h).

BTW, what do you think of the minimum (currently 1 minute)?

[twifkak, 2016/07/16 00:47:49]

Oh yeah, good question.

Short: I think it's fine.

Long: Most people precache every 10 hours, so again assuming uniformity, 1% of
requests will be < 6 minutes. So the underflow will be small.

Normally, I'd say too small and we should increase it for more granularity in
the middle, but since we're looking at correlating this with PLT and things
involving the cache, it would be interesting to look at things in the low end
(since e.g. DNS ttl is often 5 minutes or smaller).

BTW, if my rough understanding of the buckets is correct:

irb> def readable(mins); if mins > 60 * 24; "#{(mins / 60 / 24).round 2} days";
elsif mins > 60; "#{(mins / 60).round 2} hours"; else "#{mins.round 2} minutes"
end end
irb> puts (1..50).map {|i| (36.0 * 60) ** (i/50.0) }.map {|m| readable m }
1.17 minutes
1.36 minutes
1.59 minutes
1.85 minutes
2.15 minutes
2.51 minutes
2.93 minutes
3.42 minutes
3.98 minutes
4.64 minutes
5.41 minutes
6.31 minutes
7.36 minutes
8.58 minutes
10.01 minutes
11.67 minutes
13.61 minutes
15.86 minutes
18.5 minutes
21.57 minutes
25.15 minutes
29.32 minutes
34.19 minutes
39.86 minutes
46.48 minutes
54.19 minutes
1.05 hours
1.23 hours
1.43 hours
1.67 hours
1.95 hours
2.27 hours
2.65 hours
3.09 hours
3.6 hours
4.19 hours
4.89 hours
5.7 hours
6.65 hours
7.75 hours
9.04 hours
10.54 hours
12.29 hours
14.33 hours
16.71 hours
19.48 hours
22.71 hours
1.1 days
1.29 days
1.5 days

Anyway, could be wrong, but LGTM.

+  }
+}
+
 bool PrecacheDatabase::IsDatabaseAccessible() const {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(db_);