Instrumenting SSL_do_handshake and UpdateServerCert to find jank

net/socket/ssl_client_socket_openssl.cc

Index: net/socket/ssl_client_socket_openssl.cc
diff --git a/net/socket/ssl_client_socket_openssl.cc b/net/socket/ssl_client_socket_openssl.cc
index 74ac8fc7a7a577ca268e217545f85e2d82437260..42c719e288e90aba4c295f7a42a59d1989536905 100644
--- a/net/socket/ssl_client_socket_openssl.cc
+++ b/net/socket/ssl_client_socket_openssl.cc
@@ -918,14 +918,31 @@ bool SSLClientSocketOpenSSL::DoTransportIO() {
 }
 
 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.
@@ -1216,6 +1233,11 @@ void SSLClientSocketOpenSSL::UpdateServerCert() {
           "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()) {
@@ -1228,6 +1250,12 @@ void SSLClientSocketOpenSSL::UpdateServerCert() {
     // 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);