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

net/ssl/ssl_client_session_cache.cc

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/ssl/ssl_client_session_cache.h"
 
 #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"
 #include "base/trace_event/process_memory_dump.h"
 #include "net/cert/x509_util_openssl.h"
 #include "third_party/boringssl/src/include/openssl/ssl.h"
 #include "third_party/boringssl/src/include/openssl/x509.h"
 
 namespace net {
 
+SSLClientSessionCache::Entry::Entry() : lookup_count(0) {}
+SSLClientSessionCache::Entry::~Entry() = default;
+
 SSLClientSessionCache::SSLClientSessionCache(const Config& config)
     : clock_(new base::DefaultClock),
       config_(config),
       cache_(config.max_entries),
       lookups_since_flush_(0) {
   memory_pressure_listener_.reset(new base::MemoryPressureListener(base::Bind(
       &SSLClientSessionCache::OnMemoryPressure, base::Unretained(this))));
   base::MemoryCoordinatorClientRegistry::GetInstance()->Register(this);
 }
 
@@ skipping 14 matching lines @@
   lookups_since_flush_++;
   if (lookups_since_flush_ >= config_.expiration_check_count) {
     lookups_since_flush_ = 0;
     FlushExpiredSessions();
   }
 
   auto iter = cache_.Get(cache_key);
   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);
 }
 
 void SSLClientSessionCache::Insert(const std::string& cache_key,
                                    SSL_SESSION* session) {
   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() {
   base::AutoLock lock(lock_);
 
   cache_.Clear();
 }
 
 void SSLClientSessionCache::SetClockForTesting(
     std::unique_ptr<base::Clock> clock) {
@@ skipping 14 matching lines @@
   // This method can be reached from different URLRequestContexts. Since this is
   // a singleton, only log memory stats once.
   // TODO(xunjieli): Change this once crbug.com/458365 is fixed.
   if (cache_dump)
     return;
   cache_dump = pmd->CreateAllocatorDump(absolute_name);
   base::AutoLock lock(lock_);
   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;
     for (size_t i = 0; i < cert_count; ++i) {
       X509* cert = sk_X509_value(cert_chain, i);
       total_serialized_cert_size += i2d_X509(cert, nullptr);
     }
   }
   // This measures the lower bound of the serialized certificate. It doesn't
   // measure the actual memory used, which is 4x this amount (see
   // crbug.com/671420 for more details).
   cache_dump->AddScalar("serialized_cert_size",
                         base::trace_event::MemoryAllocatorDump::kUnitsBytes,
                         total_serialized_cert_size);
   cache_dump->AddScalar("cert_count",
                         base::trace_event::MemoryAllocatorDump::kUnitsObjects,
                         total_cert_count);
   cache_dump->AddScalar(base::trace_event::MemoryAllocatorDump::kNameSize,
                         base::trace_event::MemoryAllocatorDump::kUnitsBytes,
                         total_serialized_cert_size);
 }
 
 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;
     }
   }
 }
 
 void SSLClientSessionCache::OnMemoryPressure(
     base::MemoryPressureListener::MemoryPressureLevel memory_pressure_level) {
   switch (memory_pressure_level) {
@@ skipping 20 matching lines @@
       break;
     case base::MemoryState::SUSPENDED:
     // Note: Not supported at present. Fall through.
     case base::MemoryState::UNKNOWN:
       NOTREACHED();
       break;
   }
 }
 
 }  // namespace net