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 bool is_first_handshake = true;

[Ryan Sleevi, 2014/12/23 00:12:30]

Not LGTM.

SSLClientSocketOpenSSL can be used from multiple threads, even if a single
socket instance can not. You need to use thread-safe primitives to measure this.

[vadimt, 2014/12/23 00:56:13]

Done.

The logic behind the reworked implementation is:
Suppose several first handshakes start in parallel. I want all of them to be
counted as DoHandshake1_1 (i.e. the first execution) because they all should be
blocked by the initialization.

This is why I moved setting is_first_handshake to "false" after the
SSL_do_handshake call in the first branch.

I also converted to thread-safe types and operations. Don't think we need
barriers here given that the way we differentiate between first and non-first
executions is already non-deterministic, and added the non-determinism added by
not using barriers shouldn't be substantial.

+  if (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_2"));
+
+    is_first_handshake = false;
+    rv = SSL_do_handshake(ssl_);
+  } 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_);
+  }
 
   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