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..77cbd7303f23f2a6924e352b99deec43e5855e90 100644
--- a/net/socket/ssl_client_socket_openssl.cc
+++ b/net/socket/ssl_client_socket_openssl.cc
@@ -918,14 +918,30 @@ 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 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.
@@ -1216,6 +1232,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 +1249,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);