Bug 1152046 - add telemetry for time spent in connect/close. r=mayhemer

netwerk/base/nsIOService.cpp

@@ -174,6 +174,9 @@ nsIOService::nsIOService()
     , mAutoDialEnabled(false)
     , mNetworkNotifyChanged(true)
     , mPreviousWifiState(-1)
+    , mLastOfflineStateChange(PR_IntervalNow())
+    , mLastConnectivityChange(PR_IntervalNow())
+    , mLastNetworkLinkChange(PR_IntervalNow())
 {
 }
 
@@ -1001,6 +1004,7 @@ nsIOService::SetOffline(bool offline)
             if (mSocketTransportService)
                 mSocketTransportService->SetOffline(true);
 
+            mLastOfflineStateChange = PR_IntervalNow();
             if (observerService)
                 observerService->NotifyObservers(subject,
                                                  NS_IOSERVICE_OFFLINE_STATUS_TOPIC,
@@ -1021,12 +1025,14 @@ nsIOService::SetOffline(bool offline)
             if (mProxyService)
                 mProxyService->ReloadPAC();
 
+            mLastOfflineStateChange = PR_IntervalNow();
             // don't care if notification fails
             // Only send the ONLINE notification if there is connectivity
-            if (observerService && mConnectivity)
+            if (observerService && mConnectivity) {
                 observerService->NotifyObservers(subject,
                                                  NS_IOSERVICE_OFFLINE_STATUS_TOPIC,
                                                  NS_LITERAL_STRING(NS_IOSERVICE_ONLINE).get());
+            }
         }
     }
 
@@ -1077,6 +1083,10 @@ nsIOService::SetConnectivityInternal(bool aConnectivity)
     }
     mConnectivity = aConnectivity;
 
+    // This is used for PR_Connect PR_Close telemetry so it is important that
+    // we have statistic about network change event even if we are offline.
+    mLastConnectivityChange = PR_IntervalNow();
+
     nsCOMPtr<nsIObserverService> observerService =
         mozilla::services::GetObserverService();
     if (!observerService) {
@@ -1606,6 +1616,7 @@ nsIOService::OnNetworkLinkEvent(const char *data)
 
     bool isUp = true;
     if (!strcmp(data, NS_NETWORK_LINK_DATA_CHANGED)) {
+        mLastNetworkLinkChange = PR_IntervalNow();
         // CHANGED means UP/DOWN didn't change
         return NS_OK;
     } else if (!strcmp(data, NS_NETWORK_LINK_DATA_DOWN)) {

netwerk/base/nsIOService.h

@@ -18,7 +18,9 @@
 #include "nsCategoryCache.h"
 #include "nsISpeculativeConnect.h"
 #include "nsDataHashtable.h"
+#include "mozilla/Atomics.h"
 #include "mozilla/Attributes.h"
+#include "prtime.h"
 #include "nsICaptivePortalService.h"
 
 #define NS_N(x) (sizeof(x)/sizeof(*x))
@@ -79,6 +81,9 @@ public:
                                     nsAsyncRedirectVerifyHelper *helper);
 
     bool IsOffline() { return mOffline; }
+    PRIntervalTime LastOfflineStateChange() { return mLastOfflineStateChange; }
+    PRIntervalTime LastConnectivityChange() { return mLastConnectivityChange; }
+    PRIntervalTime LastNetworkLinkChange() { return mLastNetworkLinkChange; }
     bool IsShutdown() { return mShutdown; }
     bool IsLinkUp();
 
@@ -171,6 +176,14 @@ private:
     nsDataHashtable<nsUint32HashKey, int32_t> mAppsOfflineStatus;
 
     static bool                          sTelemetryEnabled;
+
+    // These timestamps are needed for collecting telemetry on PR_Connect,
+    // PR_ConnectContinue and PR_Close blocking time.  If we spend very long
+    // time in any of these functions we want to know if and what network
+    // change has happened shortly before.
+    mozilla::Atomic<PRIntervalTime>  mLastOfflineStateChange;
+    mozilla::Atomic<PRIntervalTime>  mLastConnectivityChange;
+    mozilla::Atomic<PRIntervalTime>  mLastNetworkLinkChange;
 public:
     // Used for all default buffer sizes that necko allocates.
     static uint32_t   gDefaultSegmentSize;

netwerk/base/nsSocketTransport2.cpp

@@ -1193,8 +1193,9 @@ nsSocketTransport::BuildSocket(PRFileDesc *&fd, bool &proxyTransparent, bool &us
 
         if (NS_FAILED(rv)) {
             SOCKET_LOG(("  error pushing io layer [%u:%s rv=%x]\n", i, mTypes[i], rv));
-            if (fd)
+            if (fd) {
-                PR_Close(fd);
+                CloseSocket(fd, mSocketTransportService->IsTelemetryEnabled());
+            }
         }
     }
 
@@ -1357,7 +1358,7 @@ nsSocketTransport::InitiateSocket()
     // inform socket transport about this newly created socket...
     rv = mSocketTransportService->AttachSocket(fd, this);
     if (NS_FAILED(rv)) {
-        PR_Close(fd);
+        CloseSocket(fd, mSocketTransportService->IsTelemetryEnabled());
         return rv;
     }
     mAttached = true;
@@ -1400,7 +1401,25 @@ nsSocketTransport::InitiateSocket()
 
     NetAddrToPRNetAddr(&mNetAddr, &prAddr);
 
+    // We use PRIntervalTime here because we need
+    // nsIOService::LastOfflineStateChange time and
+    // nsIOService::LastConectivityChange time to be atomic.
+    PRIntervalTime connectStarted = 0;
+    if (gSocketTransportService->IsTelemetryEnabled()) {
+        connectStarted = PR_IntervalNow();
+    }
+
     status = PR_Connect(fd, &prAddr, NS_SOCKET_CONNECT_TIMEOUT);
+
+    if (gSocketTransportService->IsTelemetryEnabled() && connectStarted) {
+        SendPRBlockingTelemetry(connectStarted,
+            Telemetry::PRCONNECT_BLOCKING_TIME_NORMAL,
+            Telemetry::PRCONNECT_BLOCKING_TIME_SHUTDOWN,
+            Telemetry::PRCONNECT_BLOCKING_TIME_CONNECTIVITY_CHANGE,
+            Telemetry::PRCONNECT_BLOCKING_TIME_LINK_CHANGE,
+            Telemetry::PRCONNECT_BLOCKING_TIME_OFFLINE);
+    }
+
     if (status == PR_SUCCESS) {
         // 
         // we are connected!
@@ -1679,7 +1698,8 @@ public:
 
   NS_IMETHOD Run()
   {
-    PR_Close(mFD);
+    nsSocketTransport::CloseSocket(mFD,
+      gSocketTransportService->IsTelemetryEnabled());
     return NS_OK;
   }
 private:
@@ -1711,7 +1731,7 @@ nsSocketTransport::ReleaseFD_Locked(PRFileDesc *fd)
     if (--mFDref == 0) {
         if (PR_GetCurrentThread() == gSocketThread) {
             SOCKET_LOG(("nsSocketTransport: calling PR_Close [this=%p]\n", this));
-            PR_Close(mFD);
+            CloseSocket(mFD, mSocketTransportService->IsTelemetryEnabled());
         } else {
             // Can't PR_Close() a socket off STS thread. Thunk it to STS to die
             STS_PRCloseOnSocketTransport(mFD);
@@ -1865,7 +1885,26 @@ nsSocketTransport::OnSocketReady(PRFileDesc *fd, int16_t outFlags)
         mPollTimeout = mTimeouts[TIMEOUT_READ_WRITE];
     }
     else if (mState == STATE_CONNECTING) {
+
+        // We use PRIntervalTime here because we need
+        // nsIOService::LastOfflineStateChange time and
+        // nsIOService::LastConectivityChange time to be atomic.
+        PRIntervalTime connectStarted = 0;
+        if (gSocketTransportService->IsTelemetryEnabled()) {
+            connectStarted = PR_IntervalNow();
+        }
+
         PRStatus status = PR_ConnectContinue(fd, outFlags);
+
+        if (gSocketTransportService->IsTelemetryEnabled() && connectStarted) {
+            SendPRBlockingTelemetry(connectStarted,
+                Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_NORMAL,
+                Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_SHUTDOWN,
+                Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_CONNECTIVITY_CHANGE,
+                Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_LINK_CHANGE,
+                Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_OFFLINE);
+        }
+
         if (status == PR_SUCCESS) {
             //
             // we are connected!
@@ -3001,3 +3040,58 @@ nsSocketTransport::PRFileDescAutoLock::SetKeepaliveVals(bool aEnabled,
     return NS_ERROR_UNEXPECTED;
 #endif
 }
+
+void
+nsSocketTransport::CloseSocket(PRFileDesc *aFd, bool aTelemetryEnabled) {
+
+    // We use PRIntervalTime here because we need
+    // nsIOService::LastOfflineStateChange time and
+    // nsIOService::LastConectivityChange time to be atomic.
+    PRIntervalTime closeStarted;
+    if (aTelemetryEnabled) {
+        closeStarted = PR_IntervalNow();
+    }
+
+    PR_Close(aFd);
+
+    if (aTelemetryEnabled) {
+        SendPRBlockingTelemetry(closeStarted,
+            Telemetry::PRCLOSE_BLOCKING_TIME_NORMAL,
+            Telemetry::PRCLOSE_BLOCKING_TIME_SHUTDOWN,
+            Telemetry::PRCLOSE_BLOCKING_TIME_CONNECTIVITY_CHANGE,
+            Telemetry::PRCLOSE_BLOCKING_TIME_LINK_CHANGE,
+            Telemetry::PRCLOSE_BLOCKING_TIME_OFFLINE);
+    }
+}
+
+void
+nsSocketTransport::SendPRBlockingTelemetry(PRIntervalTime aStart,
+                                           Telemetry::ID aIDNormal,
+                                           Telemetry::ID aIDShutdown,
+                                           Telemetry::ID aIDConnectivityChange,
+                                           Telemetry::ID aIDLinkChange,
+                                           Telemetry::ID aIDOffline)
+{
+    PRIntervalTime now = PR_IntervalNow();
+    if (gIOService->IsShutdown()) {
+        Telemetry::Accumulate(aIDShutdown,
+                              PR_IntervalToMilliseconds(now - aStart));
+
+    } else if (PR_IntervalToSeconds(now - gIOService->LastConnectivityChange())
+               < 60) {
+        Telemetry::Accumulate(aIDConnectivityChange,
+                              PR_IntervalToMilliseconds(now - aStart));
+    } else if (PR_IntervalToSeconds(now - gIOService->LastNetworkLinkChange())
+               < 60) {
+        Telemetry::Accumulate(aIDLinkChange,
+                              PR_IntervalToMilliseconds(now - aStart));
+
+    } else if (PR_IntervalToSeconds(now - gIOService->LastOfflineStateChange())
+               < 60) {
+        Telemetry::Accumulate(aIDOffline,
+                              PR_IntervalToMilliseconds(now - aStart));
+    } else {
+        Telemetry::Accumulate(aIDNormal,
+                              PR_IntervalToMilliseconds(now - aStart));
+    }
+}

netwerk/base/nsSocketTransport2.h

@@ -22,6 +22,7 @@
 #include "nsIClassInfo.h"
 #include "mozilla/net/DNS.h"
 #include "nsASocketHandler.h"
+#include "mozilla/Telemetry.h"
 
 #include "prerror.h"
 #include "nsAutoPtr.h"
@@ -157,6 +158,13 @@ public:
 
     uint64_t ByteCountReceived() override { return mInput.ByteCount(); }
     uint64_t ByteCountSent() override { return mOutput.ByteCount(); }
+    static void CloseSocket(PRFileDesc *aFd, bool aTelemetryEnabled);
+    static void SendPRBlockingTelemetry(PRIntervalTime aStart,
+        mozilla::Telemetry::ID aIDNormal,
+        mozilla::Telemetry::ID aIDShutdown,
+        mozilla::Telemetry::ID aIDConnectivityChange,
+        mozilla::Telemetry::ID aIDLinkChange,
+        mozilla::Telemetry::ID aIDOffline);
 protected:
 
     virtual ~nsSocketTransport();

toolkit/components/telemetry/Histograms.json

@@ -2484,7 +2484,112 @@
     "kind": "exponential",
     "high": "60000",
     "n_buckets": 1000,
-    "description": "Time spend blocked on poll (ms)."
+    "description": "Time spent blocked on poll (ms)."
+  },
+  "PRCONNECT_BLOCKING_TIME_NORMAL": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Connect when we are not shutting down and there has been niether a network nor an offline state change in the last 60s (ms)."
+  },
+  "PRCONNECT_BLOCKING_TIME_SHUTDOWN": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Connect during a shutdown (ms)."
+  },
+  "PRCONNECT_BLOCKING_TIME_CONNECTIVITY_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Connect when there has been the connectiviy change in the last 60s (ms)."
+  },
+  "PRCONNECT_BLOCKING_TIME_LINK_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Connect when there has been a link change in the last 60s (ms)."
+  },
+  "PRCONNECT_BLOCKING_TIME_OFFLINE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Connect when the offline state has changed in the last 60s (ms)."
+  },
+  "PRCONNECTCONTINUE_BLOCKING_TIME_NORMAL": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_ConnectContinue when we are not shutting down and there has been niether a network nor an offline state change in the last 60s (ms)."
+  },
+  "PRCONNECTCONTINUE_BLOCKING_TIME_SHUTDOWN": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_ConnectContinue during a shutdown (ms)."
+  },
+  "PRCONNECTCONTINUE_BLOCKING_TIME_CONNECTIVITY_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_ConnectContinue when there has been the connectivity change in the last 60s (ms)."
+  },
+  "PRCONNECTCONTINUE_BLOCKING_TIME_LINK_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_ConnectContinue when there has been a link change in the last 60s (ms)."
+  },
+  "PRCONNECTCONTINUE_BLOCKING_TIME_OFFLINE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_ConnectContinue when the offline state has changed in the last 60s (ms)."
+  },
+  "PRCLOSE_BLOCKING_TIME_NORMAL": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Close when we are not shutting down and there has been niether a network nor an offline state change in the last 60s (ms)."
+  },
+  "PRCLOSE_BLOCKING_TIME_SHUTDOWN": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Close during a shutdown (ms)."
+  },
+  "PRCLOSE_BLOCKING_TIME_CONNECTIVITY_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Close when there has been the connectivity change in the last 60s (ms)."
+  },
+  "PRCLOSE_BLOCKING_TIME_LINK_CHANGE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Close when there has been a link change in the last 60s (ms)."
+  },
+  "PRCLOSE_BLOCKING_TIME_OFFLINE": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 1000,
+    "description": "Time spent blocked in PR_Close when the offline state has changed in the last 60s (ms)."
   },
   "IPV4_AND_IPV6_ADDRESS_CONNECTIVITY": {
     "expires_in_version": "never",