SSLClientSessionCache: Log number of times Lookup is called per Session.

net/ssl/ssl_client_session_cache.cc

Index: net/ssl/ssl_client_session_cache.cc
diff --git a/net/ssl/ssl_client_session_cache.cc b/net/ssl/ssl_client_session_cache.cc
index 19b9d556a13c9c0c2f9d15f00a835f44254ba2e1..04a2dfa7f564617c3b5e70c981f13ae3d4852ef9 100644
--- a/net/ssl/ssl_client_session_cache.cc
+++ b/net/ssl/ssl_client_session_cache.cc
@@ -7,6 +7,7 @@
 #include <utility>
 
 #include "base/memory/memory_coordinator_client_registry.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/stringprintf.h"
 #include "base/time/clock.h"
 #include "base/time/default_clock.h"
@@ -17,6 +18,9 @@
 
 namespace net {
 
+SSLClientSessionCache::Entry::Entry() : lookup_count(0) {}
+SSLClientSessionCache::Entry::~Entry() = default;
+
 SSLClientSessionCache::SSLClientSessionCache(const Config& config)
     : clock_(new base::DefaultClock),
       config_(config),
@@ -51,12 +55,16 @@ bssl::UniquePtr<SSL_SESSION> SSLClientSessionCache::Lookup(
   if (iter == cache_.end())
     return nullptr;
 
-  SSL_SESSION* session = iter->second.get();
+  SSL_SESSION* session = iter->second->session.get();
   if (IsExpired(session, clock_->Now().ToTimeT())) {
     cache_.Erase(iter);
     return nullptr;
   }
 
+  iter->second->lookup_count++;

[davidben, 2017/01/11 16:47:49]

To simulate TLS 1.3 renewal, I think we want this number to get reset whenever
the handshake finishes.

[nharper, 2017/01/11 22:31:18]

You're right that I need to consider when the handshake finishes, but I'm not
convinced that resetting it on handshake completion is the correct behavior.

I think the metric we want to look at is "how many concurrent handshakes are
using the same session?". If I change lookup_count to be something like
concurrent_handshake_count, where it gets incremented on lookup and decremented
on handshake completion (with some carefulness to make sure increments and
decrements are always paired), I think that would give us the right number. That
still leaves open the question of when to log this number to UMA.

+  UMA_HISTOGRAM_EXACT_LINEAR("Net.SSLSessionLookupCount",
+                             iter->second->lookup_count, 20);

[davidben, 2017/01/11 16:47:50]

This will record for both HTTP/1.1 and HTTP/2 whereas we want to have the
numbers separate. Perhaps have SSLClientSessionCache return the lookup count too
and SSLClientSocket can record it based on whether the session got resumed, etc.

[nharper, 2017/01/11 22:31:18]

It sounds like returning an Entry and having SSLClientSocketImpl handle
recording the value (and possibly the bookkeeping of the count) would be
reasonable.

+
   SSL_SESSION_up_ref(session);
   return bssl::UniquePtr<SSL_SESSION>(session);
 }
@@ -66,7 +74,11 @@ void SSLClientSessionCache::Insert(const std::string& cache_key,
   base::AutoLock lock(lock_);
 
   SSL_SESSION_up_ref(session);
-  cache_.Put(cache_key, bssl::UniquePtr<SSL_SESSION>(session));
+  std::unique_ptr<Entry> entry(new Entry());
+  entry->session = bssl::UniquePtr<SSL_SESSION>(session);
+  cache_.Put(cache_key, std::move(entry));
+  // Record 0 lookups for the new session.
+  UMA_HISTOGRAM_EXACT_LINEAR("Net.SSLSessionLookupCount", 0, 20);
 }
 
 void SSLClientSessionCache::Flush() {
@@ -101,7 +113,7 @@ void SSLClientSessionCache::DumpMemoryStats(
   int total_serialized_cert_size = 0;
   int total_cert_count = 0;
   for (const auto& pair : cache_) {
-    auto entry = pair.second.get();
+    auto entry = pair.second->session.get();
     auto cert_chain = entry->x509_chain;
     size_t cert_count = sk_X509_num(cert_chain);
     total_cert_count += cert_count;
@@ -128,7 +140,7 @@ void SSLClientSessionCache::FlushExpiredSessions() {
   time_t now = clock_->Now().ToTimeT();
   auto iter = cache_.begin();
   while (iter != cache_.end()) {
-    if (IsExpired(iter->second.get(), now)) {
+    if (IsExpired(iter->second->session.get(), now)) {
       iter = cache_.Erase(iter);
     } else {
       ++iter;