bug 770264 - http connection diagnostics r=honzab

This commit is contained in:
Patrick McManus 2012-07-09 18:07:57 -04:00
parent 391b202f38
commit 088966a8d5
10 changed files with 279 additions and 0 deletions

View File

@ -876,6 +876,8 @@ pref("network.http.spdy.use-alternate-protocol", true);
pref("network.http.spdy.ping-threshold", 44);
pref("network.http.spdy.ping-timeout", 8);
pref("network.http.diagnostics", false);
// default values for FTP
// in a DSCP environment this should be 40 (0x28, or AF11), per RFC-4594,
// Section 4.8 "High-Throughput Data Service Class", and 80 (0x50, or AF22)

View File

@ -38,6 +38,8 @@ public:
nsISocketTransport *,
PRInt32);
virtual void PrintDiagnostics (nsCString &log) = 0;
const static PRUint32 kSendingChunkSize = 4096;
};

View File

@ -0,0 +1,245 @@
/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
/* vim: set sw=2 ts=8 et tw=80 : */
/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at http://mozilla.org/MPL/2.0/. */
#include "nsHttpConnectionMgr.h"
#include "nsHttpConnection.h"
#include "SpdySession2.h"
#include "SpdySession3.h"
#include "nsHttpHandler.h"
#include "nsIConsoleService.h"
using namespace mozilla;
using namespace mozilla::net;
extern PRThread *gSocketThread;
void
nsHttpConnectionMgr::PrintDiagnostics()
{
PostEvent(&nsHttpConnectionMgr::OnMsgPrintDiagnostics, 0, nsnull);
}
void
nsHttpConnectionMgr::OnMsgPrintDiagnostics(PRInt32, void *)
{
NS_ABORT_IF_FALSE(PR_GetCurrentThread() == gSocketThread, "wrong thread");
nsCOMPtr<nsIConsoleService> consoleService =
do_GetService(NS_CONSOLESERVICE_CONTRACTID);
if (!consoleService)
return;
mLogData.AppendPrintf("HTTP Connection Diagnostics\n---------------------\n");
mLogData.AppendPrintf("IsSpdyEnabled() = %d\n", gHttpHandler->IsSpdyEnabled());
mLogData.AppendPrintf("MaxSocketCount() = %d\n", gHttpHandler->MaxSocketCount());
mLogData.AppendPrintf("mNumActiveConns = %d\n", mNumActiveConns);
mLogData.AppendPrintf("mNumIdleConns = %d\n", mNumIdleConns);
mCT.Enumerate(PrintDiagnosticsCB, this);
consoleService->LogStringMessage(NS_ConvertUTF8toUTF16(mLogData).Data());
mLogData.Truncate();
}
PLDHashOperator
nsHttpConnectionMgr::PrintDiagnosticsCB(const nsACString &key,
nsAutoPtr<nsConnectionEntry> &ent,
void *closure)
{
nsHttpConnectionMgr *self = static_cast<nsHttpConnectionMgr *>(closure);
PRUint32 i;
self->mLogData.AppendPrintf(" ent host = %s hashkey = %s\n",
ent->mConnInfo->Host(), ent->mConnInfo->HashKey().get());
self->mLogData.AppendPrintf(" AtActiveConnectionLimit = %d\n",
self->AtActiveConnectionLimit(ent, NS_HTTP_ALLOW_KEEPALIVE));
self->mLogData.AppendPrintf(" RestrictConnections = %d\n",
self->RestrictConnections(ent));
self->mLogData.AppendPrintf(" Pending Q Length = %u\n",
ent->mPendingQ.Length());
self->mLogData.AppendPrintf(" Active Conns Length = %u\n",
ent->mActiveConns.Length());
self->mLogData.AppendPrintf(" Idle Conns Length = %u\n",
ent->mIdleConns.Length());
self->mLogData.AppendPrintf(" Half Opens Length = %u\n",
ent->mHalfOpens.Length());
self->mLogData.AppendPrintf(" Coalescing Key = %s\n",
ent->mCoalescingKey.get());
self->mLogData.AppendPrintf(" Spdy using = %d, tested = %d, preferred = %d\n",
ent->mUsingSpdy, ent->mTestedSpdy, ent->mSpdyPreferred);
self->mLogData.AppendPrintf(" pipelinestate = %d penalty = %d\n",
ent->mPipelineState, ent->mPipeliningPenalty);
for (i = 0; i < nsAHttpTransaction::CLASS_MAX; ++i) {
self->mLogData.AppendPrintf(" pipeline per class penalty 0x%x %d\n",
i, ent->mPipeliningClassPenalty[i]);
}
for (i = 0; i < ent->mActiveConns.Length(); ++i) {
self->mLogData.AppendPrintf(" :: Active Connection #%u\n", i);
ent->mActiveConns[i]->PrintDiagnostics(self->mLogData);
}
for (i = 0; i < ent->mIdleConns.Length(); ++i) {
self->mLogData.AppendPrintf(" :: Idle Connection #%u\n", i);
ent->mIdleConns[i]->PrintDiagnostics(self->mLogData);
}
for (i = 0; i < ent->mHalfOpens.Length(); ++i) {
self->mLogData.AppendPrintf(" :: Half Open #%u\n", i);
ent->mHalfOpens[i]->PrintDiagnostics(self->mLogData);
}
for (i = 0; i < ent->mPendingQ.Length(); ++i) {
self->mLogData.AppendPrintf(" :: Pending Transaction #%u\n", i);
ent->mPendingQ[i]->PrintDiagnostics(self->mLogData);
}
return PL_DHASH_NEXT;
}
void
nsHttpConnectionMgr::nsHalfOpenSocket::PrintDiagnostics(nsCString &log)
{
log.AppendPrintf(" has connected = %d, isSpeculative = %d\n",
HasConnected(), IsSpeculative());
TimeStamp now = TimeStamp::Now();
if (mPrimarySynStarted.IsNull())
log.AppendPrintf(" primary not started\n");
else
log.AppendPrintf(" primary started %.2fms ago\n",
(mPrimarySynStarted - now).ToMilliseconds());
if (mBackupSynStarted.IsNull())
log.AppendPrintf(" backup not started\n");
else
log.AppendPrintf(" backup started %ldms ago\n",
(mBackupSynStarted - now).ToMilliseconds());
log.AppendPrintf(" primary transport %d, backup transport %d\n",
!!mSocketTransport.get(), !!mBackupTransport.get());
}
void
nsHttpConnection::PrintDiagnostics(nsCString &log)
{
log.AppendPrintf(" CanDirectlyActivate = %d\n", CanDirectlyActivate());
log.AppendPrintf(" npncomplete = %d setupNPNCalled = %d\n",
mNPNComplete, mSetupNPNCalled);
log.AppendPrintf(" spdyVersion = %d reportedSpdy = %d everspdy = %d\n",
mUsingSpdyVersion, mReportedSpdy, mEverUsedSpdy);
log.AppendPrintf(" iskeepalive = %d dontReuse = %d isReused = %d\n",
IsKeepAlive(), mDontReuse, mIsReused);
log.AppendPrintf(" mTransaction = %d mSpdySession = %d\n",
!!mTransaction.get(), !!mSpdySession.get());
PRIntervalTime now = PR_IntervalNow();
log.AppendPrintf(" time since last read = %ums\n",
PR_IntervalToMilliseconds(now - mLastReadTime));
log.AppendPrintf(" max-read/read/written %lld/%lld/%lld\n",
mMaxBytesRead, mTotalBytesRead, mTotalBytesWritten);
log.AppendPrintf(" rtt = %ums\n", PR_IntervalToMilliseconds(mRtt));
log.AppendPrintf(" idlemonitoring = %d transactionCount=%d\n",
mIdleMonitoring, mHttp1xTransactionCount);
log.AppendPrintf(" supports pipeline = %d classification = 0x%x\n",
mSupportsPipelining, mClassification);
if (mSpdySession)
mSpdySession->PrintDiagnostics(log);
}
void
SpdySession3::PrintDiagnostics(nsCString &log)
{
log.AppendPrintf(" ::: SPDY VERSION 3\n");
log.AppendPrintf(" shouldgoaway = %d mClosed = %d CanReuse = %d nextID=0x%X\n",
mShouldGoAway, mClosed, CanReuse(), mNextStreamID);
log.AppendPrintf(" concurrent = %d maxconcurrent = %d\n",
mConcurrent, mMaxConcurrent);
log.AppendPrintf(" roomformorestreams = %d roomformoreconcurrent = %d\n",
RoomForMoreStreams(), RoomForMoreConcurrent());
log.AppendPrintf(" transactionHashCount = %d streamIDHashCount = %d\n",
mStreamTransactionHash.Count(),
mStreamIDHash.Count());
log.AppendPrintf(" Queued Stream Size = %d\n", mQueuedStreams.GetSize());
PRIntervalTime now = PR_IntervalNow();
log.AppendPrintf(" Ping Threshold = %ums next ping id = 0x%X\n",
PR_IntervalToMilliseconds(mPingThreshold),
mNextPingID);
log.AppendPrintf(" Ping Timeout = %ums\n",
PR_IntervalToMilliseconds(gHttpHandler->SpdyPingTimeout()));
log.AppendPrintf(" Idle for Any Activity (ping) = %ums\n",
PR_IntervalToMilliseconds(now - mLastReadEpoch));
log.AppendPrintf(" Idle for Data Activity = %ums\n",
PR_IntervalToMilliseconds(now - mLastDataReadEpoch));
if (mPingSentEpoch)
log.AppendPrintf(" Ping Outstanding (ping) = %ums, expired = %d\n",
PR_IntervalToMilliseconds(now - mPingSentEpoch),
now - mPingSentEpoch >= gHttpHandler->SpdyPingTimeout());
else
log.AppendPrintf(" No Ping Outstanding\n");
}
void
SpdySession2::PrintDiagnostics(nsCString &log)
{
log.AppendPrintf(" ::: SPDY VERSION 2\n");
log.AppendPrintf(" shouldgoaway = %d mClosed = %d CanReuse = %d nextID=0x%X\n",
mShouldGoAway, mClosed, CanReuse(), mNextStreamID);
log.AppendPrintf(" concurrent = %d maxconcurrent = %d\n",
mConcurrent, mMaxConcurrent);
log.AppendPrintf(" roomformorestreams = %d roomformoreconcurrent = %d\n",
RoomForMoreStreams(), RoomForMoreConcurrent());
log.AppendPrintf(" transactionHashCount = %d streamIDHashCount = %d\n",
mStreamTransactionHash.Count(),
mStreamIDHash.Count());
log.AppendPrintf(" Queued Stream Size = %d\n", mQueuedStreams.GetSize());
PRIntervalTime now = PR_IntervalNow();
log.AppendPrintf(" Ping Threshold = %ums next ping id = 0x%X\n",
PR_IntervalToMilliseconds(mPingThreshold),
mNextPingID);
log.AppendPrintf(" Ping Timeout = %ums\n",
PR_IntervalToMilliseconds(gHttpHandler->SpdyPingTimeout()));
log.AppendPrintf(" Idle for Any Activity (ping) = %ums\n",
PR_IntervalToMilliseconds(now - mLastReadEpoch));
log.AppendPrintf(" Idle for Data Activity = %ums\n",
PR_IntervalToMilliseconds(now - mLastDataReadEpoch));
if (mPingSentEpoch)
log.AppendPrintf(" Ping Outstanding (ping) = %ums, expired = %d\n",
PR_IntervalToMilliseconds(now - mPingSentEpoch),
now - mPingSentEpoch >= gHttpHandler->SpdyPingTimeout());
else
log.AppendPrintf(" No Ping Outstanding\n");
}
void
nsHttpTransaction::PrintDiagnostics(nsCString &log)
{
if (!mRequestHead)
return;
log.AppendPrintf(" ::: uri = %s\n",
nsCAutoString(mRequestHead->RequestURI()).get());
log.AppendPrintf(" caps = 0x%x\n", mCaps);
log.AppendPrintf(" priority = %d\n", mPriority);
log.AppendPrintf(" restart count = %u\n", mRestartCount);
log.AppendPrintf(" classification = 0x%x\n", mClassification);
}

View File

@ -83,6 +83,7 @@ CPPSRCS = \
SpdyStream2.cpp \
SpdySession3.cpp \
SpdyStream3.cpp \
ConnectionDiagnostics.cpp \
$(NULL)
LOCAL_INCLUDES = \

View File

@ -155,6 +155,8 @@ public:
// an overload of nsAHttpSegementReader
virtual nsresult CommitToSegmentSize(PRUint32 size);
void PrintDiagnostics (nsCString &log);
private:
enum stateType {

View File

@ -158,6 +158,8 @@ public:
PRUint32 GetServerInitialWindow() { return mServerInitialWindow; }
void PrintDiagnostics (nsCString &log);
private:
enum stateType {

View File

@ -152,6 +152,8 @@ public:
PRInt64 BytesWritten() { return mTotalBytesWritten; }
void PrintDiagnostics(nsCString &log);
private:
// called to cause the underlying socket to start speaking SSL
nsresult ProxyStartSSL();

View File

@ -199,6 +199,10 @@ public:
void ReportFailedToProcess(nsIURI *uri);
// Causes a large amount of connection diagnostic information to be
// printed to the javascript console
void PrintDiagnostics();
//-------------------------------------------------------------------------
// NOTE: functions below may be called only on the socket thread.
//-------------------------------------------------------------------------
@ -392,6 +396,7 @@ private:
bool HasConnected() { return mHasConnected; }
void PrintDiagnostics(nsCString &log);
private:
nsConnectionEntry *mEnt;
nsRefPtr<nsAHttpTransaction> mTransaction;
@ -601,6 +606,13 @@ private:
static PLDHashOperator ReadTimeoutTickCB(const nsACString &key,
nsAutoPtr<nsConnectionEntry> &ent,
void *closure);
// For diagnostics
void OnMsgPrintDiagnostics(PRInt32, void *);
static PLDHashOperator PrintDiagnosticsCB(const nsACString &key,
nsAutoPtr<nsConnectionEntry> &ent,
void *closure);
nsCString mLogData;
};
#endif // !nsHttpConnectionMgr_h__

View File

@ -1143,6 +1143,15 @@ nsHttpHandler::PrefsChanged(nsIPrefBranch *prefs, const char *pref)
PR_SecondsToInterval((PRUint16) clamped(val, 0, 0x7fffffff));
}
// on transition of network.http.diagnostics to true print
// a bunch of information to the console
if (pref && PREF_CHANGED(HTTP_PREF("diagnostics"))) {
rv = prefs->GetBoolPref(HTTP_PREF("diagnostics"), &cVar);
if (NS_SUCCEEDED(rv) && cVar) {
if (mConnMgr)
mConnMgr->PrintDiagnostics();
}
}
//
// INTL options
//

View File

@ -103,6 +103,8 @@ public:
const TimingStruct& Timings() const { return mTimings; }
enum Classifier Classification() { return mClassification; }
void PrintDiagnostics(nsCString &log);
private:
nsresult Restart();
nsresult RestartInProgress();