Instrumenting SSL_do_handshake and UpdateServerCert to find jank

net/socket/ssl_client_socket_openssl.cc

 // Copyright (c) 2012 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.
 
 // OpenSSL binding for SSLClientSocket. The class layout and general principle
 // of operation is derived from SSLClientSocketNSS.
 
 #include "net/socket/ssl_client_socket_openssl.h"
 
 #include <errno.h>
@@ skipping 900 matching lines @@
     rv = BufferSend();
     if (rv != ERR_IO_PENDING && rv != 0)
       network_moved = true;
   } while (rv > 0);
   if (transport_read_error_ == OK && BufferRecv() != ERR_IO_PENDING)
     network_moved = true;
   return network_moved;
 }
 
 int SSLClientSocketOpenSSL::DoHandshake() {
-  // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
-  tracked_objects::ScopedTracker tracking_profile1(
-      FROM_HERE_WITH_EXPLICIT_FUNCTION(
-          "424386 SSLClientSocketOpenSSL::DoHandshake1"));
-
   crypto::OpenSSLErrStackTracer err_tracer(FROM_HERE);
   int net_error = OK;
-  int rv = SSL_do_handshake(ssl_);
+
+  int rv;
+
+  // TODO(vadimt): is_first_handshake and leave only 1 call to SSL_do_handshake
+  // once crbug.com/424386 is fixed.
+  static base::subtle::Atomic32 is_first_handshake =
+      1;  // 0 is false, 1 is true.
+  if (base::subtle::NoBarrier_Load(&is_first_handshake)) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
+    tracked_objects::ScopedTracker tracking_profile1_1(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "424386 SSLClientSocketOpenSSL::DoHandshake1_1"));
+
+    rv = SSL_do_handshake(ssl_);
+    base::subtle::NoBarrier_Store(&is_first_handshake, 0);
+  } else {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
+    tracked_objects::ScopedTracker tracking_profile1_2(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "424386 SSLClientSocketOpenSSL::DoHandshake1_2"));
+
+    rv = SSL_do_handshake(ssl_);
+  }

[Ryan Sleevi, 2014/12/23 01:11:25]

Still Not LGTM.

The argument you make for coalescing the multiple initializations violates the
principle of least surprise. It's no longer "first" initialization, it's one of
many.

At the least, "is_first_handshake" should be renamed to something more
meaningful. initialization_complete ?

Before going this route, may I suggest you look at
https://code.google.com/p/chromium/codesearch#chromium/src/net/ssl/openssl_pl...

The cost spent in those methods (in particular, RsaMethodSign / EcdsaMethodSign)
will count against the SSL_do_handshake time, and we expect those methods to be
slow. Note that you're already accounting for the FetchClientCertPrivateKey &
initialization, which is currently bucketed under
https://code.google.com/p/chromium/codesearch#chromium/src/net/socket/ssl_cli...

[Ryan Sleevi, 2014/12/23 03:28:14]

Something like
if (ssl_config_.send_client_cert && ssl_config_.client_cert.get()) {
  tracked_objects::... ("DoHandshake_WithCert");
  rv = SSL_do_handshake(ssl_);
} else {
  tracked_objects::...("DoHandshake_WithoutCert");
  rv = SSL_do_handshake(ssl_);
}

 
   if (client_auth_cert_needed_) {
     // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
     tracked_objects::ScopedTracker tracking_profile2(
         FROM_HERE_WITH_EXPLICIT_FUNCTION(
             "424386 SSLClientSocketOpenSSL::DoHandshake2"));
 
     net_error = ERR_SSL_CLIENT_AUTH_CERT_NEEDED;
     // If the handshake already succeeded (because the server requests but
     // doesn't require a client cert), we need to invalidate the SSL session
@@ skipping 270 matching lines @@
   }
 }
 
 void SSLClientSocketOpenSSL::UpdateServerCert() {
   // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "424386 SSLClientSocketOpenSSL::UpdateServerCert"));
 
   server_cert_chain_->Reset(SSL_get_peer_cert_chain(ssl_));
+
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is fixed.
+  tracked_objects::ScopedTracker tracking_profile1(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "424386 SSLClientSocketOpenSSL::UpdateServerCert1"));
   server_cert_ = server_cert_chain_->AsOSChain();
 
   if (server_cert_.get()) {
     net_log_.AddEvent(
         NetLog::TYPE_SSL_CERTIFICATES_RECEIVED,
         base::Bind(&NetLogX509CertificateCallback,
                    base::Unretained(server_cert_.get())));
 
     // TODO(rsleevi): Plumb an OCSP response into the Mac system library and
     // update IsOCSPStaplingSupported for Mac. https://crbug.com/430714
     if (IsOCSPStaplingSupported()) {
 #if defined(OS_WIN)
+      // TODO(vadimt): Remove ScopedTracker below once crbug.com/424386 is
+      // fixed.
+      tracked_objects::ScopedTracker tracking_profile2(
+          FROM_HERE_WITH_EXPLICIT_FUNCTION(
+              "424386 SSLClientSocketOpenSSL::UpdateServerCert2"));
+
       const uint8_t* ocsp_response_raw;
       size_t ocsp_response_len;
       SSL_get0_ocsp_response(ssl_, &ocsp_response_raw, &ocsp_response_len);
 
       CRYPT_DATA_BLOB ocsp_response_blob;
       ocsp_response_blob.cbData = ocsp_response_len;
       ocsp_response_blob.pbData = const_cast<BYTE*>(ocsp_response_raw);
       BOOL ok = CertSetCertificateContextProperty(
           server_cert_->os_cert_handle(),
           CERT_OCSP_RESPONSE_PROP_ID,
@@ skipping 707 matching lines @@
                                             ct::SCT_STATUS_LOG_UNKNOWN));
   }
 }
 
 scoped_refptr<X509Certificate>
 SSLClientSocketOpenSSL::GetUnverifiedServerCertificateChain() const {
   return server_cert_;
 }
 
 }  // namespace net