Bug 729182 - Implement visual event tracer, http instrumentation, r=mcmanus
authorHonza Bambas <honzab.moz@firemni.cz>
Tue, 10 Jul 2012 23:49:19 +0200
changeset 101585 30a4e0cf71304537eecdfeefc70310c9928e0430
parent 101584 7f6e22f10b99eb823d4f3fe039497aa1c9f87ad6
child 101586 ad2c42efbe57309ed037463c6a297c7358a64b10
push idunknown
push userunknown
push dateunknown
reviewersmcmanus
bugs729182
milestone16.0a1
Bug 729182 - Implement visual event tracer, http instrumentation, r=mcmanus
netwerk/base/src/nsSocketTransport2.cpp
netwerk/protocol/http/nsHttpChannel.cpp
netwerk/protocol/http/nsHttpConnectionMgr.cpp
netwerk/protocol/http/nsHttpTransaction.cpp
--- a/netwerk/base/src/nsSocketTransport2.cpp
+++ b/netwerk/base/src/nsSocketTransport2.cpp
@@ -29,16 +29,18 @@
 #include "nsISocketProviderService.h"
 #include "nsISocketProvider.h"
 #include "nsISSLSocketControl.h"
 #include "nsINSSErrorsService.h"
 #include "nsIPipe.h"
 #include "nsIProgrammingLanguage.h"
 #include "nsIClassInfoImpl.h"
 
+#include "mozilla/VisualEventTracer.h"
+
 #if defined(XP_WIN) || defined(MOZ_PLATFORM_MAEMO)
 #include "nsNativeConnectionHelper.h"
 #endif
 
 using namespace mozilla;
 
 //-----------------------------------------------------------------------------
 
@@ -720,16 +722,18 @@ nsSocketTransport::~nsSocketTransport()
     NS_RELEASE(serv); // nulls argument
 }
 
 nsresult
 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);
         NS_ENSURE_ARG(proxyInfo);
     }
 
     // init socket type info
 
@@ -1150,16 +1154,17 @@ nsSocketTransport::InitiateSocket()
         PR_NetAddrToString(&mNetAddr, buf, sizeof(buf));
         SOCKET_LOG(("  trying address: %s\n", buf));
     }
 #endif
 
     // 
     // 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) {
         // 
         // we are connected!
         //
         OnSocketConnected();
     }
     else {
@@ -1374,16 +1379,18 @@ nsSocketTransport::OnSocketConnected()
     // to trample over mFDref if mFD is already set.
     {
         MutexAutoLock lock(mLock);
         NS_ASSERTION(mFD, "no socket");
         NS_ASSERTION(mFDref == 1, "wrong socket ref count");
         mFDconnected = true;
     }
 
+    MOZ_EVENT_TRACER_DONE(this, "TCP connect");
+
     SendStatus(STATUS_CONNECTED_TO);
 }
 
 PRFileDesc *
 nsSocketTransport::GetFD_Locked()
 {
     // mFD is not available to the streams while disconnected.
     if (!mFDconnected)
@@ -1996,16 +2003,17 @@ nsSocketTransport::GetQoSBits(PRUint8 *a
 NS_IMETHODIMP
 nsSocketTransport::OnLookupComplete(nsICancelable *request,
                                     nsIDNSRecord  *rec,
                                     nsresult       status)
 {
     // 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
     // transport has been shutdown.  this should never happen!  if it does
     // it means that the socket transport service was shutdown before the
     // DNS service.
     if (NS_FAILED(rv))
         NS_WARNING("unable to post DNS lookup complete message");
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -29,16 +29,17 @@
 #include "mozilla/TimeStamp.h"
 #include "nsDOMError.h"
 #include "nsAlgorithm.h"
 #include "sampler.h"
 #include "nsIConsoleService.h"
 #include "base/compiler_specific.h"
 #include "NullHttpTransaction.h"
 #include "mozilla/Attributes.h"
+#include "mozilla/VisualEventTracer.h"
 
 namespace mozilla { namespace net {
  
 namespace {
 
 // Device IDs for various cache types
 const char kDiskDeviceID[] = "disk";
 const char kMemoryDeviceID[] = "memory";
@@ -174,19 +175,24 @@ AutoRedirectVetoNotifier::ReportRedirect
         return;
 
     mChannel->mRedirectChannel = nsnull;
 
     nsCOMPtr<nsIRedirectResultListener> vetoHook;
     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
 {
 public:
     HttpCacheQuery(nsHttpChannel * channel,
                    const nsACString & clientID,
                    nsCacheStoragePolicy storagePolicy,
@@ -330,16 +336,22 @@ nsHttpChannel::~nsHttpChannel()
         mAuthProvider->Disconnect(NS_ERROR_ABORT);
 }
 
 nsresult
 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;
 
     LOG(("nsHttpChannel::Init [this=%p]\n", this));
 
     mAuthProvider =
         do_CreateInstance("@mozilla.org/network/http-channel-auth-provider;1",
@@ -2362,16 +2374,18 @@ IsSubRangeRequest(nsHttpRequestHead &aRe
     nsCAutoString byteRange;
     aRequestHead.GetHeader(nsHttp::Range, byteRange);
     return !byteRange.EqualsLiteral("bytes=0-");
 }
 
 nsresult
 nsHttpChannel::OpenCacheEntry(bool usingSSL)
 {
+    MOZ_EVENT_TRACER_EXEC(this, "OpenCacheEntry");
+
     nsresult rv;
 
     NS_ASSERTION(!mOnCacheEntryAvailableCallback, "Unexpected state");
     mLoadedFromApplicationCache = false;
 
     LOG(("nsHttpChannel::OpenCacheEntry [this=%p]", this));
 
     // make sure we're not abusing this function
@@ -4012,16 +4026,21 @@ nsHttpChannel::SetupReplacementChannel(n
 }
 
 nsresult
 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,
     // so just carry on as though this were a normal response.
     if (!location)
         return NS_ERROR_FAILURE;
 
     // make sure non-ASCII characters in the location header are escaped.
@@ -4357,16 +4376,18 @@ nsHttpChannel::GetSecurityInfo(nsISuppor
     *securityInfo = mSecurityInfo;
     NS_IF_ADDREF(*securityInfo);
     return NS_OK;
 }
 
 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);
     NS_ENSURE_TRUE(!mIsPending, NS_ERROR_IN_PROGRESS);
     NS_ENSURE_TRUE(!mWasOpened, NS_ERROR_ALREADY_OPENED);
 
     nsresult rv;
 
@@ -4987,16 +5008,17 @@ nsHttpChannel::OnStopRequest(nsIRequest 
     if (mCacheEntry && (mCacheAccess & nsICache::ACCESS_WRITE) &&
         mRequestTimeInitialized){
         FinalizeCacheEntry();
     }
     
     if (mListener) {
         LOG(("  calling OnStopRequest\n"));
         mListener->OnStopRequest(this, mListenerContext, status);
+        MOZ_EVENT_TRACER_DONE(this, "nsHttpChannel");
         mListener = 0;
         mListenerContext = 0;
     }
 
     if (mCacheEntry) {
         bool asFile = false;
         if (mInitedCacheEntry && !mCachedContentIsPartial &&
             (NS_SUCCEEDED(mStatus) || contentComplete) &&
@@ -5083,16 +5105,18 @@ nsHttpChannel::OnDataAvailable(nsIReques
         OnTransportStatus(nsnull, transportStatus, progress, progressMax);
 
         //
         // we have to manually keep the logical offset of the stream up-to-date.
         // we cannot depend solely on the offset provided, since we may have 
         // 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
         // stream offset.  it's the best we can do without a 64-bit stream
         // listener API. (Copied from nsInputStreamPump::OnStateTransfer.)
         PRUint32 odaOffset = mLogicalOffset > PR_UINT32_MAX
                            ? PR_UINT32_MAX : PRUint32(mLogicalOffset);
 
@@ -5420,16 +5444,20 @@ nsHttpChannel::ResumeAt(PRUint64 aStartP
 
 NS_IMETHODIMP
 nsHttpChannel::OnCacheEntryAvailable(nsICacheEntryDescriptor *entry,
                                      nsCacheAccessMode access,
                                      nsresult status)
 {
     MOZ_ASSERT(NS_IsMainThread());
 
+    mozilla::eventtracer::AutoEventTracer profiler(this,
+             eventtracer::eNone, eventtracer::eDone,
+             "OpenCacheEntry");
+
     nsresult rv;
 
     LOG(("nsHttpChannel::OnCacheEntryAvailable [this=%p entry=%p "
          "access=%x status=%x]\n", this, entry, access, status));
 
     if (mCacheQuery) {
         mRequestHead = mCacheQuery->mRequestHead;
         mRedirectedCachekeys = mCacheQuery->mRedirectedCachekeys.forget();
@@ -5765,16 +5793,17 @@ nsHttpChannel::OnRedirectVerifyCallback(
         // and let it be propagated to pumps.
         Cancel(result);
     }
 
     if (!mWaitingForRedirectCallback) {
         // 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
     // called we need OnStopRequest to be triggered, and if we broke out of the
     // loop above (and are thus waiting for a new callback) the suspension
     // count must be balanced in the pumps.
     if (mTransactionPump)
         mTransactionPump->Resume();
--- a/netwerk/protocol/http/nsHttpConnectionMgr.cpp
+++ b/netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ -14,16 +14,17 @@
 
 #include "nsIServiceManager.h"
 
 #include "nsIObserverService.h"
 
 #include "nsISSLSocketControl.h"
 #include "prnetdb.h"
 #include "mozilla/Telemetry.h"
+#include "mozilla/VisualEventTracer.h"
 
 using namespace mozilla;
 using namespace mozilla::net;
 
 // defined by the socket transport service while active
 extern PRThread *gSocketThread;
 
 static NS_DEFINE_CID(kSocketTransportServiceCID, NS_SOCKETTRANSPORTSERVICE_CID);
--- a/netwerk/protocol/http/nsHttpTransaction.cpp
+++ b/netwerk/protocol/http/nsHttpTransaction.cpp
@@ -24,16 +24,17 @@
 #include "nsMultiplexInputStream.h"
 #include "nsStringStream.h"
 
 #include "nsComponentManagerUtils.h" // do_CreateInstance
 #include "nsServiceManagerUtils.h"   // do_GetService
 #include "nsIHttpActivityObserver.h"
 
 #include "mozilla/FunctionTimer.h"
+#include "mozilla/VisualEventTracer.h"
 
 using namespace mozilla;
 
 //-----------------------------------------------------------------------------
 
 #ifdef DEBUG
 // defined by the socket transport service while active
 extern PRThread *gSocketThread;
@@ -165,16 +166,23 @@ nsHttpTransaction::Init(PRUint8 caps,
                         nsHttpRequestHead *requestHead,
                         nsIInputStream *requestBody,
                         bool requestBodyHasHeaders,
                         nsIEventTarget *target,
                         nsIInterfaceRequestor *callbacks,
                         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;
 
     LOG(("nsHttpTransaction::Init [this=%x caps=%x]\n", this, caps));
 
     NS_ASSERTION(cinfo, "ouch");
     NS_ASSERTION(requestHead, "ouch");
@@ -380,16 +388,21 @@ nsHttpTransaction::TakeSubTransactions(
 // nsHttpTransaction::nsAHttpTransaction
 //----------------------------------------------------------------------------
 
 void
 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
 nsHttpTransaction::GetSecurityCallbacks(nsIInterfaceRequestor **cb,
                                         nsIEventTarget        **target)
 {
     NS_IF_ADDREF(*cb = mCallbacks);
     if (target)
@@ -511,16 +524,22 @@ nsHttpTransaction::ReadRequestSegment(ns
     nsHttpTransaction *trans = (nsHttpTransaction *) closure;
     nsresult rv = trans->mReader->OnReadSegment(buf, count, countRead);
     if (NS_FAILED(rv)) return rv;
 
     if (trans->TimingEnabled() && trans->mTimings.requestStart.IsNull()) {
         // 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;
 }
 
 nsresult
 nsHttpTransaction::ReadSegments(nsAHttpSegmentReader *reader,
                                 PRUint32 count, PRUint32 *countRead)
 {
@@ -581,16 +600,21 @@ nsHttpTransaction::WritePipeSegment(nsIO
 
     nsresult rv;
     //
     // OK, now let the caller fill this segment with data.
     //
     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;
 
     // Let the transaction "play" with the buffer.  It is free to modify
     // the contents of the buffer and/or modify countWritten.
     // - Bytes in HTTP headers don't count towards countWritten, so the input
     // side of pipe (aka nsHttpChannel's mTransactionPump) won't hit
     // OnInputStreamReady until all headers have been parsed.
@@ -779,16 +803,19 @@ nsHttpTransaction::Close(nsresult reason
     mLineBuf.Truncate();
     if (mChunkedDecoder) {
         delete mChunkedDecoder;
         mChunkedDecoder = nsnull;
     }
 
     // closing this pipe triggers the channel's OnStopRequest method.
     mPipeOut->CloseWithStatus(reason);
+
+    MOZ_EVENT_TRACER_DONE(static_cast<nsAHttpTransaction*>(this),
+                          "nsHttpTransaction");
 }
 
 nsresult
 nsHttpTransaction::AddTransaction(nsAHttpTransaction *trans)
 {
     return NS_ERROR_NOT_IMPLEMENTED;
 }