Adding instrumentation to locate the source of jankiness.

net/socket/tcp_socket_win.cc

 // Copyright 2013 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.
 
 #include "net/socket/tcp_socket.h"
 #include "net/socket/tcp_socket_win.h"
 
 #include <mstcpip.h>
 
 #include "base/callback_helpers.h"
@@ skipping 232 matching lines @@
   // We grab an extra reference because there is an IO operation in progress.
   // Balanced in WriteDelegate::OnObjectSignaled().
   AddRef();
   write_watcher_.StartWatching(write_overlapped_.hEvent, &writer_);
 }
 
 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_) {
     if (core_->socket_->waiting_connect_)
       core_->socket_->DidCompleteConnect();
     else
       core_->socket_->DidSignalRead();
   }
 
   core_->Release();
 }
 
 void TCPSocketWin::Core::WriteDelegate::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_WriteDelegate_OnObjectSignaled"));
+          "418183 TCPSocketWin::Core::WriteDelegate::OnObjectSignaled"));
 
   DCHECK_EQ(object, core_->write_overlapped_.hEvent);
   if (core_->socket_)
     core_->socket_->DidCompleteWrite();
 
   core_->Release();
 }
 
 //-----------------------------------------------------------------------------
 
@@ skipping 485 matching lines @@
   *socket = tcp_socket.Pass();
   *address = ip_end_point;
   net_log_.EndEvent(NetLog::TYPE_TCP_ACCEPT,
                     CreateNetLogIPEndPointCallback(&ip_end_point));
   return OK;
 }
 
 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) {
     PLOG(ERROR) << "WSAEnumNetworkEvents()";
     return;
   }
 
   if (ev.lNetworkEvents & FD_ACCEPT) {
     int result = AcceptInternal(accept_socket_, accept_address_);
     if (result != ERR_IO_PENDING) {
@@ skipping 168 matching lines @@
   core_->read_buffer_length_ = buf_len;
   core_->WatchForRead();
   return ERR_IO_PENDING;
 }
 
 void TCPSocketWin::DidCompleteConnect() {
   DCHECK(waiting_connect_);
   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 {
     NOTREACHED();
     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);
 }
 
 void TCPSocketWin::DidCompleteWrite() {
   DCHECK(waiting_write_);
   DCHECK(!write_callback_.is_null());
 
   DWORD num_bytes, flags;
   BOOL ok = WSAGetOverlappedResult(socket_, &core_->write_overlapped_,
@@ skipping 27 matching lines @@
   core_->write_iobuffer_ = NULL;
 
   DCHECK_NE(rv, ERR_IO_PENDING);
   base::ResetAndReturn(&write_callback_).Run(rv);
 }
 
 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
     // connection closure. It is tempting to directly set rv to 0 in
     // this case, but the MSDN pages for WSAEventSelect and
     // WSAAsyncSelect recommend we still call DoRead():
     //   FD_CLOSE should only be posted after all data is read from a
     //   socket, but an application should check for remaining data upon
     //   receipt of FD_CLOSE to avoid any possibility of losing data.
     //
     // If network_events.iErrorCode[FD_READ_BIT] or
     // network_events.iErrorCode[FD_CLOSE_BIT] is nonzero, still call
     // DoRead() because recv() reports a more accurate error code
     // (WSAECONNRESET vs. WSAECONNABORTED) when the connection was
     // reset.
     rv = DoRead(core_->read_iobuffer_.get(), core_->read_buffer_length_,
                 read_callback_);
     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();
     return;
   }
 
   waiting_read_ = false;
   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);
 }
 
 }  // namespace net