Bug 729182 - Implement visual event tracer, http instrumentation, r=mcmanus

netwerk/base/src/nsSocketTransport2.cpp

@@ -34,6 +34,8 @@
 #include "nsIProgrammingLanguage.h"
 #include "nsIClassInfoImpl.h"
 
+#include "mozilla/VisualEventTracer.h"
+
 #if defined(XP_WIN) || defined(MOZ_PLATFORM_MAEMO)
 #include "nsNativeConnectionHelper.h"
 #endif
@@ -725,6 +727,8 @@ nsSocketTransport::Init(const char **types, PRUint32 typeCount,
                         const nsACString &host, PRUint16 port,
                         nsIProxyInfo *givenProxyInfo)
 {
+    MOZ_EVENT_TRACER_NAME_OBJECT(this, host.BeginReading());
+
     nsCOMPtr<nsProxyInfo> proxyInfo;
     if (givenProxyInfo) {
         proxyInfo = do_QueryInterface(givenProxyInfo);
@@ -1155,6 +1159,7 @@ nsSocketTransport::InitiateSocket()
     // 
     // Initiate the connect() to the host...  
     //
+    MOZ_EVENT_TRACER_EXEC(this, "TCP connect");
     status = PR_Connect(fd, &mNetAddr, NS_SOCKET_CONNECT_TIMEOUT);
     if (status == PR_SUCCESS) {
         // 
@@ -1379,6 +1384,8 @@ nsSocketTransport::OnSocketConnected()
         mFDconnected = true;
     }
 
+    MOZ_EVENT_TRACER_DONE(this, "TCP connect");
+
     SendStatus(STATUS_CONNECTED_TO);
 }
 
@@ -2001,6 +2008,7 @@ nsSocketTransport::OnLookupComplete(nsICancelable *request,
     // flag host lookup complete for the benefit of the ResolveHost method.
     mResolving = false;
 
+    MOZ_EVENT_TRACER_WAIT(this, "TCP connect");
     nsresult rv = PostEvent(MSG_DNS_LOOKUP_COMPLETE, status, rec);
 
     // if posting a message fails, then we should assume that the socket

netwerk/protocol/http/nsHttpChannel.cpp

@@ -34,6 +34,7 @@
 #include "base/compiler_specific.h"
 #include "NullHttpTransaction.h"
 #include "mozilla/Attributes.h"
+#include "mozilla/VisualEventTracer.h"
 
 namespace mozilla { namespace net {
  
@@ -179,9 +180,14 @@ AutoRedirectVetoNotifier::ReportRedirectResult(bool succeeded)
     NS_QueryNotificationCallbacks(mChannel, 
                                   NS_GET_IID(nsIRedirectResultListener), 
                                   getter_AddRefs(vetoHook));
+
+    nsHttpChannel * channel = mChannel;
     mChannel = nsnull;
+
     if (vetoHook)
         vetoHook->OnRedirectResult(succeeded);
+
+    MOZ_EVENT_TRACER_DONE(channel, "AsyncProcessRedirection");
 }
 
 class HttpCacheQuery : public nsRunnable, public nsICacheListener
@@ -335,6 +341,12 @@ nsHttpChannel::Init(nsIURI *uri,
                     PRUint8 caps,
                     nsProxyInfo *proxyInfo)
 {
+#ifdef MOZ_VISUAL_EVENT_TRACER
+    nsCAutoString url;
+    uri->GetAsciiSpec(url);
+    MOZ_EVENT_TRACER_NAME_OBJECT(this, url.BeginReading());
+#endif
+
     nsresult rv = HttpBaseChannel::Init(uri, caps, proxyInfo);
     if (NS_FAILED(rv))
         return rv;
@@ -2367,6 +2379,8 @@ IsSubRangeRequest(nsHttpRequestHead &aRequestHead)
 nsresult
 nsHttpChannel::OpenCacheEntry(bool usingSSL)
 {
+    MOZ_EVENT_TRACER_EXEC(this, "OpenCacheEntry");
+
     nsresult rv;
 
     NS_ASSERTION(!mOnCacheEntryAvailableCallback, "Unexpected state");
@@ -4017,6 +4031,11 @@ nsHttpChannel::AsyncProcessRedirection(PRUint32 redirectType)
     LOG(("nsHttpChannel::AsyncProcessRedirection [this=%p type=%u]\n",
         this, redirectType));
 
+    // The channel is actually starting its operation now, at least because
+    // we want it to appear like being in the waiting phase until now.
+    MOZ_EVENT_TRACER_EXEC(this, "nsHttpChannel");
+    MOZ_EVENT_TRACER_EXEC(this, "AsyncProcessRedirection");
+
     const char *location = mResponseHead->PeekHeader(nsHttp::Location);
 
     // if a location header was not given, then we can't perform the redirect,
@@ -4362,6 +4381,8 @@ nsHttpChannel::GetSecurityInfo(nsISupports **securityInfo)
 NS_IMETHODIMP
 nsHttpChannel::AsyncOpen(nsIStreamListener *listener, nsISupports *context)
 {
+    MOZ_EVENT_TRACER_WAIT(this, "nsHttpChannel");
+
     LOG(("nsHttpChannel::AsyncOpen [this=%p]\n", this));
 
     NS_ENSURE_ARG_POINTER(listener);
@@ -4992,6 +5013,7 @@ nsHttpChannel::OnStopRequest(nsIRequest *request, nsISupports *ctxt, nsresult st
     if (mListener) {
         LOG(("  calling OnStopRequest\n"));
         mListener->OnStopRequest(this, mListenerContext, status);
+        MOZ_EVENT_TRACER_DONE(this, "nsHttpChannel");
         mListener = 0;
         mListenerContext = 0;
     }
@@ -5088,6 +5110,8 @@ nsHttpChannel::OnDataAvailable(nsIRequest *request, nsISupports *ctxt,
         // already streamed some data from another source (see, for example,
         // OnDoneReadingPartialCacheEntry).
         //
+        if (!mLogicalOffset)
+            MOZ_EVENT_TRACER_EXEC(this, "nsHttpChannel");
 
         // report the current stream offset to our listener... if we've
         // streamed more than PR_UINT32_MAX, then avoid overflowing the
@@ -5425,6 +5449,10 @@ nsHttpChannel::OnCacheEntryAvailable(nsICacheEntryDescriptor *entry,
 {
     MOZ_ASSERT(NS_IsMainThread());
 
+    mozilla::eventtracer::AutoEventTracer profiler(this,
+             eventtracer::eNone, eventtracer::eDone,
+             "OpenCacheEntry");
+
     nsresult rv;
 
     LOG(("nsHttpChannel::OnCacheEntryAvailable [this=%p entry=%p "
@@ -5770,6 +5798,7 @@ nsHttpChannel::OnRedirectVerifyCallback(nsresult result)
         // We are not waiting for the callback. At this moment we must release
         // reference to the redirect target channel, otherwise we may leak.
         mRedirectChannel = nsnull;
+        MOZ_EVENT_TRACER_DONE(this, "nsHttpChannel");
     }
 
     // We always resume the pumps here. If all functions on stack have been

netwerk/protocol/http/nsHttpConnectionMgr.cpp

@@ -19,6 +19,7 @@
 #include "nsISSLSocketControl.h"
 #include "prnetdb.h"
 #include "mozilla/Telemetry.h"
+#include "mozilla/VisualEventTracer.h"
 
 using namespace mozilla;
 using namespace mozilla::net;

netwerk/protocol/http/nsHttpTransaction.cpp

@@ -29,6 +29,7 @@
 #include "nsIHttpActivityObserver.h"
 
 #include "mozilla/FunctionTimer.h"
+#include "mozilla/VisualEventTracer.h"
 
 using namespace mozilla;
 
@@ -170,6 +171,13 @@ nsHttpTransaction::Init(PRUint8 caps,
                         nsITransportEventSink *eventsink,
                         nsIAsyncInputStream **responseBody)
 {
+    MOZ_EVENT_TRACER_COMPOUND_NAME(static_cast<nsAHttpTransaction*>(this),
+                                   requestHead->PeekHeader(nsHttp::Host),
+                                   requestHead->RequestURI().BeginReading());
+
+    MOZ_EVENT_TRACER_WAIT(static_cast<nsAHttpTransaction*>(this),
+                          "nsHttpTransaction");
+
     NS_TIME_FUNCTION;
 
     nsresult rv;
@@ -385,6 +393,11 @@ nsHttpTransaction::SetConnection(nsAHttpConnection *conn)
 {
     NS_IF_RELEASE(mConnection);
     NS_IF_ADDREF(mConnection = conn);
+
+    if (conn) {
+        MOZ_EVENT_TRACER_EXEC(static_cast<nsAHttpTransaction*>(this),
+                              "nsHttpTransaction");
+    }
 }
 
 void
@@ -516,6 +529,12 @@ nsHttpTransaction::ReadRequestSegment(nsIInputStream *stream,
         // First data we're sending -> this is requestStart
         trans->mTimings.requestStart = mozilla::TimeStamp::Now();
     }
+
+    if (!trans->mSentData) {
+        MOZ_EVENT_TRACER_MARK(static_cast<nsAHttpTransaction*>(trans),
+                              "First write");
+    }
+
     trans->mSentData = true;
     return NS_OK;
 }
@@ -586,6 +605,11 @@ nsHttpTransaction::WritePipeSegment(nsIOutputStream *stream,
     rv = trans->mWriter->OnWriteSegment(buf, count, countWritten);
     if (NS_FAILED(rv)) return rv; // caller didn't want to write anything
 
+    if (!trans->mReceivedData) {
+        MOZ_EVENT_TRACER_MARK(static_cast<nsAHttpTransaction*>(trans),
+                              "First read");
+    }
+
     NS_ASSERTION(*countWritten > 0, "bad writer");
     trans->mReceivedData = true;
 
@@ -784,6 +808,9 @@ nsHttpTransaction::Close(nsresult reason)
 
     // closing this pipe triggers the channel's OnStopRequest method.
     mPipeOut->CloseWithStatus(reason);
+
+    MOZ_EVENT_TRACER_DONE(static_cast<nsAHttpTransaction*>(this),
+                          "nsHttpTransaction");
 }
 
 nsresult