Adding instrumentation to locate the source of jankiness.

net/socket/tcp_socket_win.cc

Index: net/socket/tcp_socket_win.cc
diff --git a/net/socket/tcp_socket_win.cc b/net/socket/tcp_socket_win.cc
index 0031c638165c61c8a8fe137bcfaa16c748ca876c..a45af6a7a846bd0dc4dd262ce8f68343ac64a5a9 100644
--- a/net/socket/tcp_socket_win.cc
+++ b/net/socket/tcp_socket_win.cc
@@ -250,7 +250,7 @@ void TCPSocketWin::Core::ReadDelegate::OnObjectSignaled(HANDLE object) {
   // TODO(vadimt): Remove ScopedTracker below once crbug.com/418183 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
-          "TCPSocketWin_Core_ReadDelegate_OnObjectSignaled"));
+          "418183 TCPSocketWin::Core::ReadDelegate::OnObjectSignaled"));
 
   DCHECK_EQ(object, core_->read_overlapped_.hEvent);
   if (core_->socket_) {
@@ -268,7 +268,7 @@ void TCPSocketWin::Core::WriteDelegate::OnObjectSignaled(
   // TODO(vadimt): Remove ScopedTracker below once crbug.com/418183 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
-          "TCPSocketWin_Core_WriteDelegate_OnObjectSignaled"));
+          "418183 TCPSocketWin::Core::WriteDelegate::OnObjectSignaled"));
 
   DCHECK_EQ(object, core_->write_overlapped_.hEvent);
   if (core_->socket_)
@@ -774,7 +774,8 @@ int TCPSocketWin::AcceptInternal(scoped_ptr<TCPSocketWin>* socket,
 void TCPSocketWin::OnObjectSignaled(HANDLE object) {
   // TODO(vadimt): Remove ScopedTracker below once crbug.com/418183 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
-      FROM_HERE_WITH_EXPLICIT_FUNCTION("TCPSocketWin_OnObjectSignaled"));
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "418383 TCPSocketWin::OnObjectSignaled"));
 
   WSANETWORKEVENTS ev;
   if (WSAEnumNetworkEvents(socket_, accept_event_, &ev) == SOCKET_ERROR) {
@@ -963,15 +964,29 @@ void TCPSocketWin::DidCompleteConnect() {
   DCHECK(!read_callback_.is_null());
   int result;
 
+  // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "418183 TCPSocketWin::DidCompleteConnect1"));
   WSANETWORKEVENTS events;
   int rv = WSAEnumNetworkEvents(socket_, core_->read_overlapped_.hEvent,
                                 &events);
   int os_error = 0;
   if (rv == SOCKET_ERROR) {
+    // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is
+    // fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "418183 TCPSocketWin::DidCompleteConnect2"));

[vadimt, 2015/02/05 01:17:14]

The instrumentation will interfere with WSAGetLastError, which will return 0.
This is because it makes an OS call to get time.

[Peter Kasting, 2015/02/05 01:59:38]

Done.

     NOTREACHED();
     os_error = WSAGetLastError();
     result = MapSystemError(os_error);
   } else if (events.lNetworkEvents & FD_CONNECT) {
+    // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is
+    // fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "418183 TCPSocketWin::DidCompleteConnect3"));
     os_error = events.iErrorCode[FD_CONNECT_BIT];
     result = MapConnectError(os_error);
   } else {
@@ -979,10 +994,18 @@ void TCPSocketWin::DidCompleteConnect() {
     result = ERR_UNEXPECTED;
   }
 
+  // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "418183 TCPSocketWin::DidCompleteConnect4"));
   connect_os_error_ = os_error;
   DoConnectComplete(result);
   waiting_connect_ = false;
 
+  // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "418183 TCPSocketWin::DidCompleteConnect5"));
   DCHECK_NE(result, ERR_IO_PENDING);
   base::ResetAndReturn(&read_callback_).Run(result);
 }
@@ -1030,14 +1053,27 @@ void TCPSocketWin::DidSignalRead() {
   DCHECK(waiting_read_);
   DCHECK(!read_callback_.is_null());
 
+  // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION("418183 TCPSocketWin::DidSignalRead1"));
   int os_error = 0;
   WSANETWORKEVENTS network_events;
   int rv = WSAEnumNetworkEvents(socket_, core_->read_overlapped_.hEvent,
                                 &network_events);
   if (rv == SOCKET_ERROR) {
+    // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is
+    // fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(

[vadimt, 2015/02/05 01:17:14]

Same thing

[Peter Kasting, 2015/02/05 01:59:38]

Done.

+            "418183 TCPSocketWin::DidSignalRead2"));
     os_error = WSAGetLastError();
     rv = MapSystemError(os_error);
   } else if (network_events.lNetworkEvents) {
+    // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is
+    // fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "418183 TCPSocketWin::DidSignalRead3"));
     DCHECK_EQ(network_events.lNetworkEvents & ~(FD_READ | FD_CLOSE), 0);
     // If network_events.lNetworkEvents is FD_CLOSE and
     // network_events.iErrorCode[FD_CLOSE_BIT] is 0, it is a graceful
@@ -1058,6 +1094,11 @@ void TCPSocketWin::DidSignalRead() {
     if (rv == ERR_IO_PENDING)
       return;
   } else {
+    // TODO(pkasting): Remove ScopedTracker below once crbug.com/418183 is
+    // fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "418183 TCPSocketWin::DidSignalRead4"));
     // This may happen because Read() may succeed synchronously and
     // consume all the received data without resetting the event object.
     core_->WatchForRead();
@@ -1068,10 +1109,10 @@ void TCPSocketWin::DidSignalRead() {
   core_->read_iobuffer_ = NULL;
   core_->read_buffer_length_ = 0;
 
-  DCHECK_NE(rv, ERR_IO_PENDING);
   // TODO(vadimt): Remove ScopedTracker below once crbug.com/418183 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
-      FROM_HERE_WITH_EXPLICIT_FUNCTION("TCPSocketWin::DidSignalRead"));
+      FROM_HERE_WITH_EXPLICIT_FUNCTION("418183 TCPSocketWin::DidSignalRead5"));
+  DCHECK_NE(rv, ERR_IO_PENDING);
   base::ResetAndReturn(&read_callback_).Run(rv);
 }