Bug 1257809 - "Improve telemetry for PR_Connect". r=mcmanus

--HG--
extra : rebase_source : 93d5de4062db70a9cf59045a7a42b9a8ed74e30a
This commit is contained in:
Dragana Damjanovic 2016-03-19 04:25:00 +01:00
parent e84e757350
commit 75726942c9
5 changed files with 112 additions and 13 deletions

View File

@ -1198,7 +1198,8 @@ 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) {
CloseSocket(fd, mSocketTransportService->IsTelemetryEnabled());
CloseSocket(fd,
mSocketTransportService->IsTelemetryEnabledAndNotSleepPhase());
}
}
}
@ -1376,7 +1377,8 @@ nsSocketTransport::InitiateSocket()
// inform socket transport about this newly created socket...
rv = mSocketTransportService->AttachSocket(fd, this);
if (NS_FAILED(rv)) {
CloseSocket(fd, mSocketTransportService->IsTelemetryEnabled());
CloseSocket(fd,
mSocketTransportService->IsTelemetryEnabledAndNotSleepPhase());
return rv;
}
mAttached = true;
@ -1423,13 +1425,14 @@ nsSocketTransport::InitiateSocket()
// nsIOService::LastOfflineStateChange time and
// nsIOService::LastConectivityChange time to be atomic.
PRIntervalTime connectStarted = 0;
if (gSocketTransportService->IsTelemetryEnabled()) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
connectStarted = PR_IntervalNow();
}
status = PR_Connect(fd, &prAddr, NS_SOCKET_CONNECT_TIMEOUT);
if (gSocketTransportService->IsTelemetryEnabled() && connectStarted) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase() &&
connectStarted) {
SendPRBlockingTelemetry(connectStarted,
Telemetry::PRCONNECT_BLOCKING_TIME_NORMAL,
Telemetry::PRCONNECT_BLOCKING_TIME_SHUTDOWN,
@ -1496,6 +1499,16 @@ nsSocketTransport::InitiateSocket()
// The connection was refused...
//
else {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase() &&
connectStarted) {
SendPRBlockingTelemetry(connectStarted,
Telemetry::PRCONNECT_FAIL_BLOCKING_TIME_NORMAL,
Telemetry::PRCONNECT_FAIL_BLOCKING_TIME_SHUTDOWN,
Telemetry::PRCONNECT_FAIL_BLOCKING_TIME_CONNECTIVITY_CHANGE,
Telemetry::PRCONNECT_FAIL_BLOCKING_TIME_LINK_CHANGE,
Telemetry::PRCONNECT_FAIL_BLOCKING_TIME_OFFLINE);
}
rv = ErrorAccordingToNSPR(code);
if ((rv == NS_ERROR_CONNECTION_REFUSED) && !mProxyHost.IsEmpty())
rv = NS_ERROR_PROXY_CONNECTION_REFUSED;
@ -1545,7 +1558,7 @@ nsSocketTransport::RecoverFromError()
bool tryAgain = false;
if ((mState == STATE_CONNECTING) && mDNSRecord &&
mSocketTransportService->IsTelemetryEnabled()) {
mSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
if (mNetAddr.raw.family == AF_INET) {
Telemetry::Accumulate(Telemetry::IPV4_AND_IPV6_ADDRESS_CONNECTIVITY,
UNSUCCESSFUL_CONNECTING_TO_IPV4_ADDRESS);
@ -1751,7 +1764,7 @@ public:
NS_IMETHOD Run()
{
nsSocketTransport::CloseSocket(mFD,
gSocketTransportService->IsTelemetryEnabled());
gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase());
return NS_OK;
}
private:
@ -1788,7 +1801,8 @@ nsSocketTransport::ReleaseFD_Locked(PRFileDesc *fd)
SOCKET_LOG(("Intentional leak"));
} else if (PR_GetCurrentThread() == gSocketThread) {
SOCKET_LOG(("nsSocketTransport: calling PR_Close [this=%p]\n", this));
CloseSocket(mFD, mSocketTransportService->IsTelemetryEnabled());
CloseSocket(mFD,
mSocketTransportService->IsTelemetryEnabledAndNotSleepPhase());
} else {
// Can't PR_Close() a socket off STS thread. Thunk it to STS to die
STS_PRCloseOnSocketTransport(mFD);
@ -1949,13 +1963,14 @@ nsSocketTransport::OnSocketReady(PRFileDesc *fd, int16_t outFlags)
// nsIOService::LastOfflineStateChange time and
// nsIOService::LastConectivityChange time to be atomic.
PRIntervalTime connectStarted = 0;
if (gSocketTransportService->IsTelemetryEnabled()) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
connectStarted = PR_IntervalNow();
}
PRStatus status = PR_ConnectContinue(fd, outFlags);
if (gSocketTransportService->IsTelemetryEnabled() && connectStarted) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase() &&
connectStarted) {
SendPRBlockingTelemetry(connectStarted,
Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_NORMAL,
Telemetry::PRCONNECTCONTINUE_BLOCKING_TIME_SHUTDOWN,
@ -1970,7 +1985,7 @@ nsSocketTransport::OnSocketReady(PRFileDesc *fd, int16_t outFlags)
//
OnSocketConnected();
if (mSocketTransportService->IsTelemetryEnabled()) {
if (mSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
if (mNetAddr.raw.family == AF_INET) {
Telemetry::Accumulate(
Telemetry::IPV4_AND_IPV6_ADDRESS_CONNECTIVITY,

View File

@ -25,6 +25,7 @@
#include "mozilla/Telemetry.h"
#include "nsThreadUtils.h"
#include "nsIFile.h"
#include "nsIWidget.h"
using namespace mozilla;
using namespace mozilla::net;
@ -111,6 +112,7 @@ nsSocketTransportService::nsSocketTransportService()
, mMaxTimePerPollIter(100)
, mTelemetryEnabledPref(false)
, mMaxTimeForPrClosePref(PR_SecondsToInterval(5))
, mSleepPhase(false)
, mProbedMaxCount(false)
{
NS_ASSERTION(NS_IsMainThread(), "wrong thread");
@ -558,6 +560,8 @@ nsSocketTransportService::Init()
if (obsSvc) {
obsSvc->AddObserver(this, "profile-initial-state", false);
obsSvc->AddObserver(this, "last-pb-context-exited", false);
obsSvc->AddObserver(this, NS_WIDGET_SLEEP_OBSERVER_TOPIC, true);
obsSvc->AddObserver(this, NS_WIDGET_WAKE_OBSERVER_TOPIC, true);
}
mInitialized = true;
@ -606,6 +610,13 @@ nsSocketTransportService::Shutdown()
if (obsSvc) {
obsSvc->RemoveObserver(this, "profile-initial-state");
obsSvc->RemoveObserver(this, "last-pb-context-exited");
obsSvc->RemoveObserver(this, NS_WIDGET_SLEEP_OBSERVER_TOPIC);
obsSvc->RemoveObserver(this, NS_WIDGET_WAKE_OBSERVER_TOPIC);
}
if (mAfterWakeUpTimer) {
mAfterWakeUpTimer->Cancel();
mAfterWakeUpTimer = nullptr;
}
mozilla::net::NetworkActivityMonitor::Shutdown();
@ -1271,6 +1282,27 @@ nsSocketTransportService::Observe(nsISupports *subject,
NS_ENSURE_SUCCESS(rv, rv);
}
if (!strcmp(topic, NS_TIMER_CALLBACK_TOPIC)) {
nsCOMPtr<nsITimer> timer = do_QueryInterface(subject);
if (timer == mAfterWakeUpTimer) {
mAfterWakeUpTimer = nullptr;
mSleepPhase = false;
}
} else if (!strcmp(topic, NS_WIDGET_SLEEP_OBSERVER_TOPIC)) {
mSleepPhase = true;
if (mAfterWakeUpTimer) {
mAfterWakeUpTimer->Cancel();
mAfterWakeUpTimer = nullptr;
}
} else if (!strcmp(topic, NS_WIDGET_WAKE_OBSERVER_TOPIC)) {
if (mSleepPhase && !mAfterWakeUpTimer) {
mAfterWakeUpTimer = do_CreateInstance("@mozilla.org/timer;1");
if (mAfterWakeUpTimer) {
mAfterWakeUpTimer->Init(this, 2000, nsITimer::TYPE_ONE_SHOT);
}
}
}
return NS_OK;
}

View File

@ -19,6 +19,7 @@
#include "mozilla/net/DashboardTypes.h"
#include "mozilla/Atomics.h"
#include "mozilla/TimeStamp.h"
#include "nsITimer.h"
class nsASocketHandler;
struct PRPollDesc;
@ -111,7 +112,8 @@ public:
// Returns true if keepalives are enabled in prefs.
bool IsKeepaliveEnabled() { return mKeepaliveEnabledPref; }
bool IsTelemetryEnabled() { return mTelemetryEnabledPref; }
bool IsTelemetryEnabledAndNotSleepPhase() { return mTelemetryEnabledPref &&
!mSleepPhase; }
PRIntervalTime MaxTimeForPrClosePref() {return mMaxTimeForPrClosePref; }
protected:
@ -240,6 +242,11 @@ private:
mozilla::Atomic<bool, mozilla::Relaxed> mTelemetryEnabledPref;
mozilla::Atomic<PRIntervalTime, mozilla::Relaxed> mMaxTimeForPrClosePref;
// Between a computer going to sleep and waking up the PR_*** telemetry
// will be corrupted - so do not record it.
mozilla::Atomic<bool, mozilla::Relaxed> mSleepPhase;
nsCOMPtr<nsITimer> mAfterWakeUpTimer;
void OnKeepaliveEnabledPrefChange();
void NotifyKeepaliveEnabledPrefChange(SocketContext *sock);

View File

@ -786,13 +786,13 @@ nsUDPSocket::CloseSocket()
} else {
PRIntervalTime closeStarted = 0;
if (gSocketTransportService->IsTelemetryEnabled()) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
closeStarted = PR_IntervalNow();
}
PR_Close(mFD);
if (gSocketTransportService->IsTelemetryEnabled()) {
if (gSocketTransportService->IsTelemetryEnabledAndNotSleepPhase()) {
PRIntervalTime now = PR_IntervalNow();
if (gIOService->IsNetTearingDown()) {
Telemetry::Accumulate(Telemetry::PRCLOSE_UDP_BLOCKING_TIME_SHUTDOWN,

View File

@ -2590,6 +2590,51 @@
"n_buckets": 1000,
"description": "Time spent blocked in PR_Connect when the offline state has changed in the last 60s (ms)."
},
"PRCONNECT_FAIL_BLOCKING_TIME_NORMAL": {
"bug_numbers": [1257809],
"alert_emails": ["ddamjanovic@mozilla.com"],
"expires_in_version": "never",
"kind": "exponential",
"high": 60000,
"n_buckets": 100,
"description": "Time spent blocked in a failed 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_FAIL_BLOCKING_TIME_SHUTDOWN": {
"bug_numbers": [1257809],
"alert_emails": ["ddamjanovic@mozilla.com"],
"expires_in_version": "never",
"kind": "exponential",
"high": 60000,
"n_buckets": 100,
"description": "Time spent blocked in a failed PR_Connect during a shutdown (ms)."
},
"PRCONNECT_FAIL_BLOCKING_TIME_CONNECTIVITY_CHANGE": {
"bug_numbers": [1257809],
"alert_emails": ["ddamjanovic@mozilla.com"],
"expires_in_version": "never",
"kind": "exponential",
"high": 60000,
"n_buckets": 100,
"description": "Time spent blocked in a failed PR_Connect when there has been the connectiviy change in the last 60s (ms)."
},
"PRCONNECT_FAIL_BLOCKING_TIME_LINK_CHANGE": {
"bug_numbers": [1257809],
"alert_emails": ["ddamjanovic@mozilla.com"],
"expires_in_version": "never",
"kind": "exponential",
"high": 60000,
"n_buckets": 100,
"description": "Time spent blocked in a failed PR_Connect when there has been a link change in the last 60s (ms)."
},
"PRCONNECT_FAIL_BLOCKING_TIME_OFFLINE": {
"bug_numbers": [1257809],
"alert_emails": ["ddamjanovic@mozilla.com"],
"expires_in_version": "never",
"kind": "exponential",
"high": 60000,
"n_buckets": 100,
"description": "Time spent blocked in a failed PR_Connect when the offline state has changed in the last 60s (ms)."
},
"PRCONNECTCONTINUE_BLOCKING_TIME_NORMAL": {
"expires_in_version": "never",
"kind": "exponential",